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
agent: systemd-nspawn running (pid 52)
client: systemd-nspawn running (pid 53)
relay: systemd-nspawn running (pid 54)
agent: Waiting for journal at /build/vm-state-agent/var/log/journal...
client: Waiting for journal at /build/vm-state-client/var/log/journal...
relay: Waiting for journal at /build/vm-state-relay/var/log/journal...
(finished: start all VMs, in 0.00 seconds)
relay: waiting for unit flakelet-relay.service
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.
nixos-nspawn(agent): TAP vde-tap1 not found; container will be isolated from VDE
nixos-nspawn(agent): 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(relay): TAP vde-tap1 not found; container will be isolated from VDE
nixos-nspawn(relay): 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.
░ Spawning container client on /build/vm-state-client.
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 relay on /build/vm-state-relay.
░ Spawning container agent on /build/vm-state-agent.
agent # No journal files were found.
agent # No journal boot entry found for the specified boot (+0).
relay # No journal files were found.
relay # No journal boot entry found for the specified boot (+0).
client # No journal files were found.
client # No journal boot entry found for the specified boot (+0).
agent # [84900.952206] agent systemd-journald[57]: Journal started
agent # [84900.952248] agent systemd-journald[57]: Runtime Journal (/run/log/journal/fdb647dac4674313a4b71cbec1ef960b) is 8M, max 4G, 3.9G free.
agent # [84900.962708] agent systemd[1]: Finished Apply Kernel Variables.
agent # [84900.974264] agent systemd[1]: Finished Create Static Device Nodes in /dev gracefully.
agent # [84901.007506] agent systemd[1]: Starting Flush Journal to Persistent Storage...
agent # [84901.008209] agent systemd[1]: Starting Create Static Device Nodes in /dev...
agent # [84901.016401] agent systemd-journald[57]: Time spent on flushing to /var/log/journal/fdb647dac4674313a4b71cbec1ef960b is 1.744ms for 6 entries.
agent # [84901.016401] agent systemd-journald[57]: System Journal (/var/log/journal/fdb647dac4674313a4b71cbec1ef960b) is 512B, max 4G, 3.9G free.
agent # [84901.028938] agent systemd[1]: Finished Create Static Device Nodes in /dev.
agent # [84901.029793] agent systemd[1]: Reached target Preparation for Local File Systems.
agent # [84901.029925] agent systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys
agent # [84901.039076] agent systemd[1]: Finished Flush Journal to Persistent Storage.
agent # [84901.112361] agent systemd[1]: Finished Firewall.
client # [84900.944399] client systemd-journald[57]: Journal started
relay # [84900.953840] relay systemd-journald[57]: Journal started
client # [84900.944440] client systemd-journald[57]: Runtime Journal (/run/log/journal/703e661a5c0b4c66b458fca3cfd9754f) is 8M, max 4G, 3.9G free.
relay # [84900.953885] relay systemd-journald[57]: Runtime Journal (/run/log/journal/c570373fcc0240218ae60b94573eace1) is 8M, max 4G, 3.9G free.
client # [84900.954034] client systemd[1]: Finished Apply Kernel Variables.
relay # [84900.965393] relay systemd[1]: Finished Apply Kernel Variables.
client # [84900.965821] client systemd[1]: Finished Create Static Device Nodes in /dev gracefully.
relay # [84900.977497] relay systemd[1]: Finished Create Static Device Nodes in /dev gracefully.
client # [84900.981403] client systemd[1]: Starting Flush Journal to Persistent Storage...
relay # [84901.007557] relay systemd[1]: Starting Flush Journal to Persistent Storage...
client # [84900.982113] client systemd[1]: Starting Create Static Device Nodes in /dev...
relay # [84901.008390] relay systemd[1]: Starting Create Static Device Nodes in /dev...
relay # [84901.017052] relay systemd-journald[57]: Time spent on flushing to /var/log/journal/c570373fcc0240218ae60b94573eace1 is 1.503ms for 6 entries.
client # [84901.013810] client systemd-journald[57]: Time spent on flushing to /var/log/journal/703e661a5c0b4c66b458fca3cfd9754f is 1.563ms for 6 entries.
relay # [84901.017052] relay systemd-journald[57]: System Journal (/var/log/journal/c570373fcc0240218ae60b94573eace1) is 512B, max 4G, 3.9G free.
relay # [84901.028133] relay systemd[1]: Finished Create Static Device Nodes in /dev.
relay # [84901.028893] relay systemd[1]: Reached target Preparation for Local File Systems.
relay # [84901.029012] relay systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys
client # [84901.013810] client systemd-journald[57]: System Journal (/var/log/journal/703e661a5c0b4c66b458fca3cfd9754f) is 512B, max 4G, 3.9G free.
relay # [84901.041572] relay systemd[1]: Finished Flush Journal to Persistent Storage.
relay # [84901.127751] relay systemd[1]: Finished Firewall.
relay # [84901.954649] relay systemd[1]: Mounting /run/wrappers...
client # [84901.022086] client systemd[1]: Finished Create Static Device Nodes in /dev.
client # [84901.022777] client systemd[1]: Reached target Preparation for Local File Systems.
client # [84901.022885] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys
client # [84901.035034] client systemd[1]: Finished Flush Journal to Persistent Storage.
client # [84901.102179] client systemd[1]: Finished Firewall.
relay # [84902.003960] relay systemd[1]: Mounted /run/wrappers.
relay # [84902.004777] relay systemd[1]: Reached target Local File Systems.
relay # [84902.006176] relay systemd[1]: Listening on Boot Loader Control Service Socket.
relay # [84902.007457] relay systemd[1]: Starting Create SUID/SGID Wrappers...
relay # [84902.007505] relay systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container
relay # [84902.008664] relay systemd[1]: Starting Save Transient machine-id to Disk...
relay # [84902.009724] relay systemd[1]: Starting Create System Files and Directories...
relay # [84902.030911] relay systemd-tmpfiles[169]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted
relay # [84902.031367] relay systemd-tmpfiles[169]: fchmod() of /var/log/journal failed: Operation not permitted
relay # [84902.031692] relay systemd-tmpfiles[169]: fchmod() of /var/log/journal/c570373fcc0240218ae60b94573eace1 failed: Operation not permitted
relay # [84902.032072] relay systemd-tmpfiles[169]: fchmod() of /run/log/journal failed: Operation not permitted
agent # [84901.986765] agent systemd[1]: Mounting /run/wrappers...
agent # [84902.025667] agent systemd[1]: Mounted /run/wrappers.
agent # [84902.026941] agent systemd[1]: Reached target Local File Systems.
agent # [84902.028386] agent systemd[1]: Listening on Boot Loader Control Service Socket.
agent # [84902.029769] agent systemd[1]: Starting Create SUID/SGID Wrappers...
agent # [84902.029820] agent systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container
agent # [84902.030728] agent systemd[1]: Starting Save Transient machine-id to Disk...
agent # [84902.031667] agent systemd[1]: Starting Create System Files and Directories...
agent # [84902.051168] agent systemd-tmpfiles[161]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted
agent # [84902.051615] agent systemd-tmpfiles[161]: fchmod() of /var/log/journal failed: Operation not permitted
agent # [84902.051967] agent systemd-tmpfiles[161]: fchmod() of /var/log/journal/fdb647dac4674313a4b71cbec1ef960b failed: Operation not permitted
agent # [84902.052392] agent systemd-tmpfiles[161]: fchmod() of /run/log/journal failed: Operation not permitted
client # [84901.986761] client systemd[1]: Mounting /run/wrappers...
client # [84902.026241] client systemd[1]: Mounted /run/wrappers.
client # [84902.027534] client systemd[1]: Reached target Local File Systems.
client # [84902.028925] client systemd[1]: Listening on Boot Loader Control Service Socket.
client # [84902.030199] client systemd[1]: Starting Create SUID/SGID Wrappers...
client # [84902.030246] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container
client # [84902.031225] client systemd[1]: Starting Save Transient machine-id to Disk...
client # [84902.032111] client systemd[1]: Starting Create System Files and Directories...
client # [84902.052766] client systemd-tmpfiles[161]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted
client # [84902.053203] client systemd-tmpfiles[161]: fchmod() of /var/log/journal failed: Operation not permitted
client # [84902.053544] client systemd-tmpfiles[161]: fchmod() of /var/log/journal/703e661a5c0b4c66b458fca3cfd9754f failed: Operation not permitted
client # [84902.053913] client systemd-tmpfiles[161]: fchmod() of /run/log/journal failed: Operation not permitted
relay # [84902.034229] relay systemd[1]: Finished Create System Files and Directories.
relay # [84902.034367] relay suid-sgid-wrappers-start[176]: chmod: changing permissions of '/run/wrappers/wrappers.YIHsudkI03/chsh': Operation not permitted
relay # [84902.045939] relay systemd[1]: suid-sgid-wrappers.service: Main process exited, code=exited, status=1/FAILURE
relay # [84902.046183] relay systemd[1]: suid-sgid-wrappers.service: Failed with result 'exit-code'.
relay # [84902.046321] relay systemd[1]: Failed to start Create SUID/SGID Wrappers.
relay # [84902.048703] relay systemd[1]: Starting Rebuild Journal Catalog...
relay # [84902.049365] relay systemd[1]: Starting Record System Boot/Shutdown in UTMP...
relay # [84902.061047] relay systemd[1]: Finished Record System Boot/Shutdown in UTMP.
relay # [84902.074782] relay systemd[1]: Finished Rebuild Journal Catalog.
relay # [84902.075956] relay systemd[1]: Starting Update is Completed...
relay # [84902.088539] relay systemd[1]: Finished Update is Completed.
relay # [84902.088699] relay systemd[1]: Reached target System Initialization.
relay # [84902.088772] relay systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container
relay # [84902.088799] relay systemd[1]: Started Daily Cleanup of Temporary Directories.
relay # [84902.088816] relay systemd[1]: Reached target Timer Units.
relay # [84902.088938] relay systemd[1]: Listening on D-Bus System Message Bus Socket.
relay # [84902.089184] relay systemd[1]: Listening on Nix Daemon Socket.
relay # [84902.089297] relay systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.
relay # [84902.089313] relay systemd[1]: Reached target Socket Units.
relay # [84902.089346] relay systemd[1]: Reached target Basic System.
relay # [84902.090654] relay systemd[1]: Started device-mock.service.
relay # [84902.091366] relay systemd[1]: Starting Re-link flakelet services at boot...
relay # [84902.092288] relay systemd[1]: Starting Import lastlog data into lastlog2 database...
relay # [84902.093306] relay systemd[1]: Starting Name Service Cache Daemon (nsncd)...
relay # [84902.094079] relay systemd[1]: Starting resolvconf update...
relay # [84902.104362] relay systemd[1]: Finished Re-link flakelet services at boot.
relay # [84902.105863] relay systemd[1]: Starting Reconcile flakelet services with the host configuration...
relay # [84902.113523] relay systemd[1]: Finished Import lastlog data into lastlog2 database.
relay # [84902.120549] relay systemd[1]: Finished Reconcile flakelet services with the host configuration.
relay # [84902.173575] relay systemd[1]: Finished resolvconf update.
relay # [84902.174246] relay systemd[1]: Reached target Preparation for Network.
relay # [84902.175288] relay systemd[1]: Starting Address configuration of eth1...
relay # [84902.176618] relay systemd[1]: Starting Extra networking commands....
relay # [84902.194547] relay network-addresses-eth1-start[245]: adding address 192.168.1.3/24... done
relay # [84902.200077] relay network-addresses-eth1-start[245]: adding address 2001:db8:1::3/64... done
client # [84902.055830] client suid-sgid-wrappers-start[168]: chmod: changing permissions of '/run/wrappers/wrappers.1RMV5ysm0P/chsh': Operation not permitted
client # [84902.056752] client systemd[1]: Finished Create System Files and Directories.
client # [84902.081514] client systemd[1]: suid-sgid-wrappers.service: Main process exited, code=exited, status=1/FAILURE
agent # [84902.052675] agent suid-sgid-wrappers-start[168]: chmod: changing permissions of '/run/wrappers/wrappers.zTLlGtOMN2/chsh': Operation not permitted
client # [84902.081557] client systemd[1]: suid-sgid-wrappers.service: Failed with result 'exit-code'.
client # [84902.081605] client systemd[1]: Failed to start Create SUID/SGID Wrappers.
agent # [84902.058081] agent systemd[1]: suid-sgid-wrappers.service: Main process exited, code=exited, status=1/FAILURE
client # [84902.084637] client systemd[1]: Starting Rebuild Journal Catalog...
agent # [84902.058124] agent systemd[1]: suid-sgid-wrappers.service: Failed with result 'exit-code'.
client # [84902.085345] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...
client # [84902.097970] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.
agent # [84902.058176] agent systemd[1]: Failed to start Create SUID/SGID Wrappers.
client # [84902.106146] client systemd[1]: Finished Rebuild Journal Catalog.
agent # [84902.058653] agent systemd[1]: Finished Create System Files and Directories.
client # [84902.107460] client systemd[1]: Starting Update is Completed...
agent # [84902.085514] agent systemd[1]: Starting Rebuild Journal Catalog...
client # [84902.116629] client systemd[1]: Finished Update is Completed.
agent # [84902.086175] agent systemd[1]: Starting Record System Boot/Shutdown in UTMP...
client # [84902.116726] client systemd[1]: Reached target System Initialization.
agent # [84902.098560] agent systemd[1]: Finished Record System Boot/Shutdown in UTMP.
client # [84902.116796] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container
agent # [84902.107016] agent systemd[1]: Finished Rebuild Journal Catalog.
client # [84902.116825] client systemd[1]: Started Daily Cleanup of Temporary Directories.
agent # [84902.108189] agent systemd[1]: Starting Update is Completed...
client # [84902.116844] client systemd[1]: Reached target Timer Units.
agent # [84902.118610] agent systemd[1]: Finished Update is Completed.
client # [84902.116957] client systemd[1]: Listening on D-Bus System Message Bus Socket.
agent # [84902.119379] agent systemd[1]: Reached target System Initialization.
client # [84902.117158] client systemd[1]: Listening on Nix Daemon Socket.
agent # [84902.119541] agent systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container
client # [84902.117272] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.
agent # [84902.119615] agent systemd[1]: Started Daily Cleanup of Temporary Directories.
client # [84902.117287] client systemd[1]: Reached target Socket Units.
agent # [84902.119644] agent systemd[1]: Reached target Timer Units.
client # [84902.117319] client systemd[1]: Reached target Basic System.
agent # [84902.119863] agent systemd[1]: Listening on D-Bus System Message Bus Socket.
client # [84902.118718] client systemd[1]: Starting Import lastlog data into lastlog2 database...
agent # [84902.120135] agent systemd[1]: Listening on Nix Daemon Socket.
client # [84902.119552] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...
agent # [84902.120335] agent systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.
client # [84902.120211] client systemd[1]: Starting resolvconf update...
agent # [84902.120361] agent systemd[1]: Reached target Socket Units.
client # [84902.150415] client systemd[1]: Finished Import lastlog data into lastlog2 database.
agent # [84902.120415] agent systemd[1]: Reached target Basic System.
client # [84902.220978] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
agent # [84902.122255] agent systemd[1]: Starting Re-link flakelet services at boot...
client # [84902.221997] client systemd[1]: Finished Save Transient machine-id to Disk.
agent # [84902.123283] agent systemd[1]: Starting Import lastlog data into lastlog2 database...
client # [84902.222218] client systemd[1]: nscd.service: Deactivated successfully.
agent # [84902.124847] agent systemd[1]: Starting Name Service Cache Daemon (nsncd)...
client # [84902.222370] client systemd[1]: Stopped Name Service Cache Daemon (nsncd).
agent # [84902.125733] agent systemd[1]: Starting resolvconf update...
client # [84902.224187] client systemd[1]: Finished resolvconf update.
agent # [84902.138552] agent systemd[1]: Finished Re-link flakelet services at boot.
client # [84902.226332] client systemd[1]: Reached target Preparation for Network.
agent # [84902.141719] agent systemd[1]: Starting Reconcile flakelet services with the host configuration...
client # [84902.227228] client systemd[1]: Starting Address configuration of eth1...
agent # [84902.150652] agent systemd[1]: Finished Import lastlog data into lastlog2 database.
client # [84902.227963] client systemd[1]: Starting Extra networking commands....
agent # [84902.155307] agent systemd[1]: Finished Reconcile flakelet services with the host configuration.
client # [84902.233886] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...
agent # [84902.220873] agent systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
agent # [84902.221943] agent systemd[1]: Finished Save Transient machine-id to Disk.
agent # [84902.222142] agent systemd[1]: nscd.service: Deactivated successfully.
agent # [84902.222356] agent systemd[1]: Stopped Name Service Cache Daemon (nsncd).
agent # [84902.224183] agent systemd[1]: Finished resolvconf update.
agent # [84902.226385] agent systemd[1]: Reached target Preparation for Network.
agent # [84902.227226] agent systemd[1]: Starting Address configuration of eth1...
agent # [84902.227922] agent systemd[1]: Starting Extra networking commands....
agent # [84902.233888] agent systemd[1]: Starting Name Service Cache Daemon (nsncd)...
client # [84902.283820] client network-addresses-eth1-start[236]: adding address 192.168.1.2/24... done
client # [84902.287112] client network-addresses-eth1-start[236]: adding address 2001:db8:1::2/64... done
client # [84902.290643] client systemd[1]: Finished Address configuration of eth1.
client # [84902.330937] client systemd[1]: Finished Extra networking commands..
client # [84902.331092] client systemd[1]: Reached target Network.
client # [84902.404299] client systemd[1]: nscd.service: Deactivated successfully.
client # [84902.404490] client systemd[1]: Stopped Name Service Cache Daemon (nsncd).
client # [84902.407278] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...
agent # [84902.286355] agent network-addresses-eth1-start[240]: adding address 192.168.1.1/24... done
agent # [84902.289375] agent network-addresses-eth1-start[240]: adding address 2001:db8:1::1/64... done
agent # [84902.294525] agent systemd[1]: Finished Address configuration of eth1.
agent # [84902.336643] agent systemd[1]: Finished Extra networking commands..
agent # [84902.337353] agent systemd[1]: Reached target Network.
agent # [84902.338585] agent systemd[1]: Starting flakelet-agent...
agent # [84902.339253] agent systemd[1]: Starting Update flakelet service app...
agent # [84902.339944] agent systemd[1]: Starting Update flakelet service other...
agent # [84902.374631] agent systemd[1]: nscd.service: Deactivated successfully.
agent # [84902.386384] agent systemd[1]: Stopped Name Service Cache Daemon (nsncd).
agent # [84902.390551] agent systemd[1]: Starting Name Service Cache Daemon (nsncd)...
agent # [84902.400292] agent flakelet[306]: other: using prebuilt artifact /nix/store/hmr990n0b4v6rpzrcpyyw738r9xi7z95-flakelet-other-v1
agent # [84902.401166] agent flakelet[306]: other: activating generation 1
agent # [84902.401303] agent flakelet[305]: app: using prebuilt artifact /nix/store/hysydfr96ds875vr0jgw5rjxi4p39h2j-flakelet-app-v1
agent # [84902.402021] agent flakelet[305]: app: activating generation 1
agent # [84902.409368] agent systemd[1]: Reload requested from client PID 313 ('systemctl') (unit flakelet-other.service)...
agent # [84902.409461] agent systemd[1]: Reloading...
agent # [84902.449106] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:23.578226Z","level":"WARN","message":"SRV _flakelet-relay._tcp.test: lookup failed","target":"flakelet_agent"}
relay # [84902.227301] relay systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
relay # [84902.228357] relay systemd[1]: Finished Save Transient machine-id to Disk.
relay # [84902.229012] relay systemd[1]: nscd.service: Deactivated successfully.
relay # [84902.233919] relay systemd[1]: Stopped Name Service Cache Daemon (nsncd).
relay # [84902.235598] relay systemd[1]: Finished Address configuration of eth1.
relay # [84902.266677] relay systemd[1]: Starting Name Service Cache Daemon (nsncd)...
relay # [84902.266930] relay systemd[1]: Finished Extra networking commands..
relay # [84902.267848] relay systemd[1]: Reached target Network.
relay # [84902.269142] relay systemd[1]: Starting Dnsmasq Daemon...
relay # [84902.270157] relay systemd[1]: Starting Nginx Web Server...
relay # [84902.271043] relay systemd[1]: Starting Update flakelet service flakelet-relay...
relay # [84902.282852] relay flakelet[310]: flakelet-relay: using prebuilt artifact /nix/store/7zwd9c7nvf99s9x33v3aakwppzscxpbq-flakelet-flakelet-relay
relay # [84902.283579] relay flakelet[310]: flakelet-relay: activating generation 1
relay # [84902.287514] relay systemd[1]: Reload requested from client PID 314 ('systemctl') (unit flakelet-flakelet-relay.service)...
relay # [84902.287563] relay systemd[1]: Reloading...
relay # [84902.720396] relay nsncd[298]: Sep 06 06:14:23.849 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
relay # [84902.811931] relay systemd[1]: Reloading finished in 523 ms.
relay # [84902.948058] relay systemd[1]: Started Name Service Cache Daemon (nsncd).
relay # [84902.950456] relay systemd[1]: Reached target Host and Network Name Lookups.
relay # [84902.950674] relay systemd[1]: Reached target User and Group Name Lookups.
relay # [84902.953397] relay systemd[1]: Starting User Login Management...
relay # [84902.954213] relay systemd[1]: Starting Permit User Sessions...
relay # [84902.967861] relay systemd[1]: Reload requested from client PID 357 ('systemctl') (unit flakelet-flakelet-relay.service)...
relay # [84902.967948] relay systemd[1]: Reloading...
client # [84902.684079] client nsncd[303]: Sep 06 06:14:23.813 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
client # [84902.684043] client systemd[1]: Started Name Service Cache Daemon (nsncd).
client # [84902.684126] client systemd[1]: Reached target Host and Network Name Lookups.
client # [84902.684185] client systemd[1]: Reached target User and Group Name Lookups.
client # [84902.686019] client systemd[1]: Starting User Login Management...
client # [84902.686900] client systemd[1]: Starting Permit User Sessions...
client # [84902.720484] client systemd[1]: Finished Permit User Sessions.
client # [84902.722013] client systemd[1]: Started Console Getty.
client # [84902.722043] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0
client # [84902.722060] client systemd[1]: Reached target Login Prompts.
agent # [84902.712337] agent nsncd[311]: Sep 06 06:14:23.841 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
agent # [84902.818296] agent systemd[1]: Reloading finished in 407 ms.
agent # [84902.952072] agent systemd[1]: Started flakelet-agent.
agent # [84902.952233] agent systemd[1]: Started Name Service Cache Daemon (nsncd).
agent # [84902.953895] agent systemd[1]: Reload requested from client PID 314 ('systemctl') (unit flakelet-app.service)...
agent # [84902.953947] agent systemd[1]: Reloading...
relay # [84902.972095] relay dnsmasq-pre-start[360]: dnsmasq: syntax check OK.
relay # [84903.347541] relay systemd[1]: Reloading finished in 378 ms.
agent # [84903.352784] agent systemd[1]: Reloading finished in 398 ms.
agent # [84903.529252] agent systemd[1]: Reached target Host and Network Name Lookups.
agent # [84903.529367] agent systemd[1]: Reached target User and Group Name Lookups.
agent # [84903.530835] agent systemd[1]: Starting User Login Management...
agent # [84903.531910] agent systemd[1]: Starting Permit User Sessions...
agent # [84903.540986] agent systemd[1]: Reload requested from client PID 764 ('systemctl') (unit flakelet-other.service)...
agent # [84903.541088] agent systemd[1]: Reloading...
relay # [84903.528703] relay systemd[1]: Finished Permit User Sessions.
relay # [84903.537690] relay systemd[1]: Started Console Getty.
relay # [84903.537809] relay systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0
relay # [84903.537941] relay systemd[1]: Reached target Login Prompts.
relay # [84903.540571] relay systemd[1]: Starting flakelet-relay...
agent # [84903.929112] agent systemd[1]: Reloading finished in 387 ms.
agent # [84903.997466] agent systemd[1]: Finished Permit User Sessions.
agent # [84904.001989] agent systemd[1]: Started Console Getty.
agent # [84904.002107] agent systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0
agent # [84904.002249] agent systemd[1]: Reached target Login Prompts.
agent # [84904.002611] agent systemd[1]: Reload requested from client PID 767 ('systemctl') (unit flakelet-app.service)...
agent # [84904.002639] agent systemd[1]: Reloading...
relay # [84904.041258] relay nginx-pre-start[402]: nginx: the configuration file /nix/store/01avjj26wcihp926xgasszcj5s0k7cbs-nginx.conf syntax is ok
relay # [84904.041940] relay nginx-pre-start[402]: nginx: configuration file /nix/store/01avjj26wcihp926xgasszcj5s0k7cbs-nginx.conf test is successful
relay # [84904.056658] relay systemd[1]: Started Nginx Web Server.
relay # [84904.217663] relay systemd[1]: Starting D-Bus System Message Bus...
client # [84904.182866] client systemd-logind[315]: New seat seat0.
client # [84904.183222] client systemd[1]: Started User Login Management.
client # [84904.184804] client systemd[1]: Starting D-Bus System Message Bus...
client # [84904.193291] client systemd[1]: Starting linger-users.service...
client # [84904.227518] client systemd[1]: linger-users.service: Deactivated successfully.
client # [84904.227814] client systemd[1]: Finished linger-users.service.
client # [84904.228039] client systemd[1]: Reached target Multi-User System.
agent # [84904.409122] agent systemd[1]: Reloading finished in 406 ms.
agent # [84904.487084] agent systemd[1]: Starting other v1...
agent # [84904.521360] agent systemd[1]: Starting app v1...
agent # [84904.525247] agent systemd[1]: Started other v1.
agent # [84904.531580] agent systemd[1]: Started app v1.
agent # [84904.554734] agent flakelet[306]: other: updated to generation 1
agent # [84904.555780] agent systemd[1]: Finished Update flakelet service other.
agent # [84904.559697] agent flakelet[305]: app: updated to generation 1
agent # [84904.561264] agent systemd[1]: Finished Update flakelet service app.
agent # [84904.561403] agent systemd[1]: Reached target flakelet managed services.
relay # [84904.514957] relay systemd-logind[354]: New seat seat0.
relay # [84904.515210] relay systemd[1]: Started User Login Management.
relay # [84904.521537] relay systemd[1]: Starting linger-users.service...
relay # [84904.534674] relay systemd[1]: linger-users.service: Deactivated successfully.
relay # [84904.534943] relay systemd[1]: Finished linger-users.service.
relay # [84904.745565] relay dbus-broker-launch[408]: Looking up NSS user entry for 'systemd-timesync'...
relay # [84904.746680] relay dbus-broker-launch[408]: NSS returned no entry for 'systemd-timesync'
relay # [84904.746680] relay dbus-broker-launch[408]: Invalid user-name in /nix/store/27h4g2jdw18vrabfh6p1l0n8ss5dhbp5-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"
relay # [84904.747560] relay systemd[1]: Started D-Bus System Message Bus.
relay # [84904.757620] relay dbus-broker-launch[408]: Ready
relay # [84904.761789] relay systemd[1]: Started Dnsmasq Daemon.
relay # [84904.763723] relay dnsmasq[395]: started, version 2.93 cachesize 150
relay # [84904.763731] relay dnsmasq[395]: compile time options: IPv6 GNU-getopt DBus no-UBus no-i18n IDN2 DHCP DHCPv6 no-Lua TFTP conntrack ipset nftset auth DNSSEC loop-detect inotify dumpfile
relay # [84904.763736] relay dnsmasq[395]: DBus support enabled: connected to system bus
relay # [84904.763744] relay dnsmasq[395]: no upstream servers configured - please set them from DBus
relay # [84904.763829] relay dnsmasq[395]: read /etc/hosts - 9 names
client # [84904.763765] client dbus-broker-launch[325]: Looking up NSS user entry for 'systemd-timesync'...
client # [84904.765057] client dbus-broker-launch[325]: NSS returned no entry for 'systemd-timesync'
client # [84904.765057] client dbus-broker-launch[325]: Invalid user-name in /nix/store/bja873g16bkdjc9pijmr630xwdjl32m3-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"
client # [84904.766271] client systemd[1]: Started D-Bus System Message Bus.
client # [84904.766783] client systemd[1]: Startup finished in 4.258s.
client # [84904.772207] client dbus-broker-launch[325]: Ready
agent # [84905.032411] agent systemd-logind[765]: New seat seat0.
agent # [84905.032888] agent systemd[1]: Started User Login Management.
agent # [84905.034447] agent systemd[1]: Starting D-Bus System Message Bus...
agent # [84905.035538] agent systemd[1]: Starting linger-users.service...
agent # [84905.078140] agent systemd[1]: linger-users.service: Deactivated successfully.
agent # [84905.078584] agent systemd[1]: Finished linger-users.service.
agent # [84905.079978] agent systemd[1]: Reached target Multi-User System.
relay # [84905.575521] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:26.704654Z","level":"INFO","message":"listening on 127.0.0.1:7400","target":"flakelet_relay::relay::server"}
relay # [84905.576149] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:26.705138Z","level":"INFO","message":"listening on [::]:7443","target":"flakelet_relay::relay::server"}
relay # [84905.576078] relay systemd[1]: Started flakelet-relay.
relay # [84905.594666] relay systemd[1]: Starting health for flakelet-relay...
relay # [84905.826519] relay systemd[1]: flakelet-relay-health.service: Deactivated successfully.
agent # [84905.456809] agent dbus-broker-launch[841]: Looking up NSS user entry for 'systemd-timesync'...
agent # [84905.458515] agent dbus-broker-launch[841]: NSS returned no entry for 'systemd-timesync'
agent # [84905.458515] agent dbus-broker-launch[841]: Invalid user-name in /nix/store/q3c2gxfm178wqgzv8m87na4aa72wxc04-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"
agent # [84905.459262] agent systemd[1]: Started D-Bus System Message Bus.
agent # [84905.459834] agent systemd[1]: Startup finished in 4.949s.
agent # [84905.464541] agent dbus-broker-launch[841]: Ready
relay: (finished: waiting for unit flakelet-relay.service, in 6.16 seconds)
relay: waiting for unit nginx.service
relay: (finished: waiting for unit nginx.service, in 0.01 seconds)
agent: waiting for unit flakelet.target
agent: (finished: waiting for unit flakelet.target, in 0.02 seconds)
agent: waiting for unit flakelet-agent.service
agent: (finished: waiting for unit flakelet-agent.service, in 0.02 seconds)
client: waiting for unit multi-user.target
client: (finished: waiting for unit multi-user.target, in 0.01 seconds)
relay: waiting for success: curl -sf http://127.0.0.1:7400/metrics | grep -q 'agent_up{host="agent"} 1'
relay # [84905.827129] relay systemd[1]: Finished health for flakelet-relay.
relay # [84905.875140] relay flakelet[310]: flakelet-relay: updated to generation 1
relay # [84905.876250] relay systemd[1]: Finished Update flakelet service flakelet-relay.
relay # [84905.878209] relay systemd[1]: Reached target flakelet managed services.
relay # [84905.878571] relay systemd[1]: Reached target Multi-User System.
relay # [84905.878876] relay systemd[1]: Startup finished in 5.370s.
agent # [84907.558538] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:28.687684Z","level":"INFO","message":"connected","relay":"https://relay:7443","relay_name":"relay","relay_version":"0.1.0","host":"agent","target":"flakelet_relay::agent::conn"}
relay # [84907.558796] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:28.687968Z","level":"INFO","message":"agent connected","host":"agent","version":"0.1.0","flakelets":"[Named { name: \"app\", generation: Some(1), revision: Some(\"prebuilt:app\") }, Named { name: \"other\", generation: Some(1), revision: Some(\"prebuilt:other\") }]","target":"flakelet_relay::relay::agent_conn"}
relay: (finished: waiting for success: curl -sf http://127.0.0.1:7400/metrics | grep -q 'agent_up{host="agent"} 1', in 2.05 seconds)
agent: must succeed: systemctl is-active app.service other.service
agent: (finished: must succeed: systemctl is-active app.service other.service, in 0.01 seconds)
subtest: deploy with client certificate, relay found via SRV
agent: must succeed: jq '.services.app.prebuilt="/nix/store/6ili1vxjlag9d7dy0bxrbxk6bpi5qh9p-flakelet-app-v2"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json
agent: (finished: must succeed: jq '.services.app.prebuilt="/nix/store/6ili1vxjlag9d7dy0bxrbxk6bpi5qh9p-flakelet-app-v2"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json, in 0.01 seconds)
client: must succeed: push --relay-srv test --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/app 2>&1
agent # [84908.284278] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:29.413504Z","level":"INFO","message":"start","id":"dd05e7f5f3c9b9817dd220b61bba6d04","flakelet":"app","rule":"admins","relay":"relay","caller":"Some(\"x509:email:admin@example.org\")","target":"flakelet_relay::agent::conn"}
agent # [84908.285090] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:29.414362Z","level":"INFO","message":"update starting","flakelet":"app","ids":"[\"dd05e7f5f3c9b9817dd220b61bba6d04\"]","target":"flakelet_relay::agent::jobs"}
agent # [84908.341448] agent systemd[1]: Starting flakelet update app (via relay)...
agent # [84908.373774] agent systemd[1]: Started flakelet update app (via relay).
agent # [84908.379608] agent flakelet[870]: app: using prebuilt artifact /nix/store/6ili1vxjlag9d7dy0bxrbxk6bpi5qh9p-flakelet-app-v2
agent # [84908.380290] agent flakelet[870]: app: activating generation 2
agent # [84908.394238] agent systemd[1]: Stopping app v1...
agent # [84908.394760] agent systemd[1]: app.service: Deactivated successfully.
agent # [84908.395137] agent systemd[1]: Stopped app v1.
agent # [84908.415097] agent systemd[1]: Reload requested from client PID 877 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84908.415189] agent systemd[1]: Reloading...
relay # [84908.283337] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:29.412557Z","level":"INFO","message":"deploy accepted","job":"7f630172135f1077f4a87a31e7dfb9d9","caller":"x509:email:admin@example.org","targets":"[\"agent/app\"]","target":"flakelet_relay::relay::api"}
agent # [84908.777258] agent systemd[1]: Reloading finished in 361 ms.
agent # [84908.860331] agent systemd[1]: Reload requested from client PID 907 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84908.860380] agent systemd[1]: Reloading...
agent # [84909.203307] agent systemd[1]: Reloading finished in 342 ms.
agent # [84909.286851] agent systemd[1]: Reload requested from client PID 936 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84909.286893] agent systemd[1]: Reloading...
agent # [84909.642521] agent systemd[1]: Reloading finished in 355 ms.
agent # [84909.727686] agent systemd[1]: Reload requested from client PID 967 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84909.727774] agent systemd[1]: Reloading...
agent # [84910.072244] agent systemd[1]: Reloading finished in 343 ms.
agent # [84910.158246] agent systemd[1]: Starting app v2...
agent # [84910.199686] agent systemd[1]: Started app v2.
agent # [84910.221633] agent flakelet[870]: app: updated to generation 2
agent # [84910.224967] agent systemd[1]: flakelet-relay-job-app.service: Deactivated successfully.
client: (finished: must succeed: push --relay-srv test --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/app 2>&1, in 3.02 seconds)
agent: must succeed: systemctl show app.service -p Description | grep -q 'app v2'
agent: (finished: must succeed: systemctl show app.service -p Description | grep -q 'app v2', in 0.01 seconds)
agent: must succeed: journalctl -u flakelet-relay-job-app.service | grep -q 'generation 2'
agent: (finished: must succeed: journalctl -u flakelet-relay-job-app.service | grep -q 'generation 2', in 0.01 seconds)
(finished: subtest: deploy with client certificate, relay found via SRV, in 3.06 seconds)
subtest: deploy with OIDC token, sub principal
agent: must succeed: jq '.services.app.prebuilt="/nix/store/hysydfr96ds875vr0jgw5rjxi4p39h2j-flakelet-app-v1"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json
agent: (finished: must succeed: jq '.services.app.prebuilt="/nix/store/hysydfr96ds875vr0jgw5rjxi4p39h2j-flakelet-app-v1"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json, in 0.01 seconds)
client: must succeed: echo '{"groups": []}' | step crypto jwt sign --key /nix/store/r7sclamg09v434w8zjlfnrcrn1w79wh6-flakelet-relay-test-issuer/jwk.json --iss https://relay:8443 --aud flakelet-relay --sub 'repo:github:example/app:ref:refs/heads/main' --exp $(( $(date +%s) + 300 )) --jti $(head -c8 /dev/urandom | base32)
client: (finished: must succeed: echo '{"groups": []}' | step crypto jwt sign --key /nix/store/r7sclamg09v434w8zjlfnrcrn1w79wh6-flakelet-relay-test-issuer/jwk.json --iss https://relay:8443 --aud flakelet-relay --sub 'repo:github:example/app:ref:refs/heads/main' --exp $(( $(date +%s) + 300 )) --jti $(head -c8 /dev/urandom | base32), in 0.05 seconds)
client: must succeed: FLAKELET_RELAY_TOKEN_COMMAND='echo eyJhbGciOiJFZERTQSIsImtpZCI6ImsxIiwidHlwIjoiSldUIn0.eyJhdWQiOiJmbGFrZWxldC1yZWxheSIsImV4cCI6MTc4ODY3NTU3MiwiZ3JvdXBzIjpbXSwiaWF0IjoxNzg4Njc1MjcyLCJpc3MiOiJodHRwczovL3JlbGF5Ojg0NDMiLCJqdGkiOiJTSUxFNllPN1A0VlBTPT09IiwibmJmIjoxNzg4Njc1MjcyLCJzdWIiOiJyZXBvOmdpdGh1YjpleGFtcGxlL2FwcDpyZWY6cmVmcy9oZWFkcy9tYWluIn0.HQuGntogsht3ERYbnBfLpdawDAKI5Bx7OiIn1ar3dHvgnYHILW_b5E9oz55vpuk2YVIcA5xurXIyqnkZSjQWDw' push --relay https://relay:7443 deploy agent/app 2>&1
agent # [84911.280814] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:32.410030Z","level":"INFO","message":"update finished","flakelet":"app","status":"Updated","generation":"Some(2)","target":"flakelet_relay::agent::jobs"}
agent # [84911.410247] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:32.539439Z","level":"INFO","message":"start","id":"f600d91a22cf57f15cb4e5781b592650","flakelet":"app","rule":"ci","relay":"relay","caller":"Some(\"oidc:mock:repo:github:example/app:ref:refs/heads/main\")","target":"flakelet_relay::agent::conn"}
agent # [84911.410771] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:32.540065Z","level":"INFO","message":"update starting","flakelet":"app","ids":"[\"f600d91a22cf57f15cb4e5781b592650\"]","target":"flakelet_relay::agent::jobs"}
agent # [84911.468051] agent systemd[1]: Starting flakelet update app (via relay)...
agent # [84911.504525] agent systemd[1]: Started flakelet update app (via relay).
agent # [84911.508834] agent flakelet[1025]: app: using prebuilt artifact /nix/store/hysydfr96ds875vr0jgw5rjxi4p39h2j-flakelet-app-v1
agent # [84911.509560] agent flakelet[1025]: app: activating generation 3
agent # [84911.527012] agent systemd[1]: Stopping app v2...
agent # [84911.527289] agent systemd[1]: app.service: Deactivated successfully.
agent # [84911.527496] agent systemd[1]: Stopped app v2.
agent # [84911.542319] agent systemd[1]: Reload requested from client PID 1032 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84911.542409] agent systemd[1]: Reloading...
relay # [84911.281835] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:32.411036Z","level":"INFO","message":"deploy finished","job":"7f630172135f1077f4a87a31e7dfb9d9","ok":true,"target":"flakelet_relay::relay::api"}
relay # [84911.409697] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:32.538953Z","level":"INFO","message":"deploy accepted","job":"79a6eb067ad5df00df61f597ee17baba","caller":"oidc:mock:repo:github:example/app:ref:refs/heads/main","targets":"[\"agent/app\"]","target":"flakelet_relay::relay::api"}
agent # [84911.902999] agent systemd[1]: Reloading finished in 359 ms.
agent # [84911.987962] agent systemd[1]: Reload requested from client PID 1062 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84911.988033] agent systemd[1]: Reloading...
agent # [84912.331060] agent systemd[1]: Reloading finished in 342 ms.
agent # [84912.423041] agent systemd[1]: Reload requested from client PID 1091 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84912.423100] agent systemd[1]: Reloading...
agent # [84912.764568] agent systemd[1]: Reloading finished in 340 ms.
agent # [84912.854114] agent systemd[1]: Reload requested from client PID 1122 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84912.854165] agent systemd[1]: Reloading...
agent # [84913.202480] agent systemd[1]: Reloading finished in 347 ms.
agent # [84913.290951] agent systemd[1]: Starting app v1...
agent # [84913.325353] agent systemd[1]: Started app v1.
agent # [84913.351161] agent flakelet[1025]: app: updated to generation 3
agent # [84913.354581] agent systemd[1]: flakelet-relay-job-app.service: Deactivated successfully.
client: (finished: must succeed: FLAKELET_RELAY_TOKEN_COMMAND='echo eyJhbGciOiJFZERTQSIsImtpZCI6ImsxIiwidHlwIjoiSldUIn0.eyJhdWQiOiJmbGFrZWxldC1yZWxheSIsImV4cCI6MTc4ODY3NTU3MiwiZ3JvdXBzIjpbXSwiaWF0IjoxNzg4Njc1MjcyLCJpc3MiOiJodHRwczovL3JlbGF5Ojg0NDMiLCJqdGkiOiJTSUxFNllPN1A0VlBTPT09IiwibmJmIjoxNzg4Njc1MjcyLCJzdWIiOiJyZXBvOmdpdGh1YjpleGFtcGxlL2FwcDpyZWY6cmVmcy9oZWFkcy9tYWluIn0.HQuGntogsht3ERYbnBfLpdawDAKI5Bx7OiIn1ar3dHvgnYHILW_b5E9oz55vpuk2YVIcA5xurXIyqnkZSjQWDw' push --relay https://relay:7443 deploy agent/app 2>&1, in 3.04 seconds)
(finished: subtest: deploy with OIDC token, sub principal, in 3.11 seconds)
subtest: policy denies uncovered target
client: must fail: FLAKELET_RELAY_TOKEN_COMMAND='echo eyJhbGciOiJFZERTQSIsImtpZCI6ImsxIiwidHlwIjoiSldUIn0.eyJhdWQiOiJmbGFrZWxldC1yZWxheSIsImV4cCI6MTc4ODY3NTU3MiwiZ3JvdXBzIjpbXSwiaWF0IjoxNzg4Njc1MjcyLCJpc3MiOiJodHRwczovL3JlbGF5Ojg0NDMiLCJqdGkiOiJTSUxFNllPN1A0VlBTPT09IiwibmJmIjoxNzg4Njc1MjcyLCJzdWIiOiJyZXBvOmdpdGh1YjpleGFtcGxlL2FwcDpyZWY6cmVmcy9oZWFkcy9tYWluIn0.HQuGntogsht3ERYbnBfLpdawDAKI5Bx7OiIn1ar3dHvgnYHILW_b5E9oz55vpuk2YVIcA5xurXIyqnkZSjQWDw' push --relay https://relay:7443 deploy agent/other 2>&1
client: (finished: must fail: FLAKELET_RELAY_TOKEN_COMMAND='echo eyJhbGciOiJFZERTQSIsImtpZCI6ImsxIiwidHlwIjoiSldUIn0.eyJhdWQiOiJmbGFrZWxldC1yZWxheSIsImV4cCI6MTc4ODY3NTU3MiwiZ3JvdXBzIjpbXSwiaWF0IjoxNzg4Njc1MjcyLCJpc3MiOiJodHRwczovL3JlbGF5Ojg0NDMiLCJqdGkiOiJTSUxFNllPN1A0VlBTPT09IiwibmJmIjoxNzg4Njc1MjcyLCJzdWIiOiJyZXBvOmdpdGh1YjpleGFtcGxlL2FwcDpyZWY6cmVmcy9oZWFkcy9tYWluIn0.HQuGntogsht3ERYbnBfLpdawDAKI5Bx7OiIn1ar3dHvgnYHILW_b5E9oz55vpuk2YVIcA5xurXIyqnkZSjQWDw' push --relay https://relay:7443 deploy agent/other 2>&1, in 0.02 seconds)
(finished: subtest: policy denies uncovered target, in 0.02 seconds)
subtest: claim principal from groups, unchanged counts as success
client: must succeed: echo '{"groups": ["wheel"]}' | step crypto jwt sign --key /nix/store/r7sclamg09v434w8zjlfnrcrn1w79wh6-flakelet-relay-test-issuer/jwk.json --iss https://relay:8443 --aud flakelet-relay --sub 'someone' --exp $(( $(date +%s) + 300 )) --jti $(head -c8 /dev/urandom | base32)
client: (finished: must succeed: echo '{"groups": ["wheel"]}' | step crypto jwt sign --key /nix/store/r7sclamg09v434w8zjlfnrcrn1w79wh6-flakelet-relay-test-issuer/jwk.json --iss https://relay:8443 --aud flakelet-relay --sub 'someone' --exp $(( $(date +%s) + 300 )) --jti $(head -c8 /dev/urandom | base32), in 0.05 seconds)
client: must succeed: FLAKELET_RELAY_TOKEN_COMMAND='echo eyJhbGciOiJFZERTQSIsImtpZCI6ImsxIiwidHlwIjoiSldUIn0.eyJhdWQiOiJmbGFrZWxldC1yZWxheSIsImV4cCI6MTc4ODY3NTU3NSwiZ3JvdXBzIjpbIndoZWVsIl0sImlhdCI6MTc4ODY3NTI3NSwiaXNzIjoiaHR0cHM6Ly9yZWxheTo4NDQzIiwianRpIjoiMzNIVENLRk5LVk5CMj09PSIsIm5iZiI6MTc4ODY3NTI3NSwic3ViIjoic29tZW9uZSJ9.XdcDm7E1XcvU6CnM0p2QN7ka7a67eiNkwDRcs5HJ4GTnccSYMeNWudMD-F7iq5mPIWffpHWXyXtSpm6yI99XCA' push --relay https://relay:7443 deploy agent/other 2>&1
relay # [84914.415425] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:35.544639Z","level":"INFO","message":"deploy finished","job":"79a6eb067ad5df00df61f597ee17baba","ok":true,"target":"flakelet_relay::relay::api"}
relay # [84914.509882] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:35.639095Z","level":"INFO","message":"deploy accepted","job":"1e20c51c4f0451f1c80a79960289ba28","caller":"oidc:mock:groups:wheel\noidc:mock:someone","targets":"[\"agent/other\"]","target":"flakelet_relay::relay::api"}
agent # [84914.414552] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:35.543764Z","level":"INFO","message":"update finished","flakelet":"app","status":"Updated","generation":"Some(3)","target":"flakelet_relay::agent::jobs"}
agent # [84914.510320] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:35.639522Z","level":"INFO","message":"start","id":"116f713ffd806c1abf7467b4e7bca3b5","flakelet":"other","rule":"admins","relay":"relay","caller":"Some(\"oidc:mock:groups:wheel\\noidc:mock:someone\")","target":"flakelet_relay::agent::conn"}
agent # [84914.510701] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:35.639953Z","level":"INFO","message":"update starting","flakelet":"other","ids":"[\"116f713ffd806c1abf7467b4e7bca3b5\"]","target":"flakelet_relay::agent::jobs"}
agent # [84914.569385] agent systemd[1]: Starting flakelet update other (via relay)...
agent # [84914.618407] agent systemd[1]: Started flakelet update other (via relay).
agent # [84914.623511] agent flakelet[1171]: other: using prebuilt artifact /nix/store/hmr990n0b4v6rpzrcpyyw738r9xi7z95-flakelet-other-v1
agent # [84914.624365] agent flakelet[1171]: other: up to date
agent # [84914.626855] agent systemd[1]: flakelet-relay-job-other.service: Deactivated successfully.
client: (finished: must succeed: FLAKELET_RELAY_TOKEN_COMMAND='echo eyJhbGciOiJFZERTQSIsImtpZCI6ImsxIiwidHlwIjoiSldUIn0.eyJhdWQiOiJmbGFrZWxldC1yZWxheSIsImV4cCI6MTc4ODY3NTU3NSwiZ3JvdXBzIjpbIndoZWVsIl0sImlhdCI6MTc4ODY3NTI3NSwiaXNzIjoiaHR0cHM6Ly9yZWxheTo4NDQzIiwianRpIjoiMzNIVENLRk5LVk5CMj09PSIsIm5iZiI6MTc4ODY3NTI3NSwic3ViIjoic29tZW9uZSJ9.XdcDm7E1XcvU6CnM0p2QN7ka7a67eiNkwDRcs5HJ4GTnccSYMeNWudMD-F7iq5mPIWffpHWXyXtSpm6yI99XCA' push --relay https://relay:7443 deploy agent/other 2>&1, in 0.69 seconds)
(finished: subtest: claim principal from groups, unchanged counts as success, in 0.74 seconds)
subtest: push login via device flow, cached token used afterwards
client: must succeed: push login --issuer https://relay:8443 --client-id flakelet-relay 2>&1
relay # [84915.174959] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:36.304215Z","level":"INFO","message":"deploy finished","job":"1e20c51c4f0451f1c80a79960289ba28","ok":true,"target":"flakelet_relay::relay::api"}
relay # [84915.200262] relay 93sn3sv24fj26ksccpppzwg6kbf10s4w-device-mock[185]: 127.0.0.1 - - [06/Sep/2026 06:14:36] "POST /device HTTP/1.1" 200 -
agent # [84915.174276] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:36.303492Z","level":"INFO","message":"update finished","flakelet":"other","status":"Unchanged","generation":"Some(1)","target":"flakelet_relay::agent::jobs"}
relay # [84916.205627] relay 93sn3sv24fj26ksccpppzwg6kbf10s4w-device-mock[185]: 127.0.0.1 - - [06/Sep/2026 06:14:37] "POST /token HTTP/1.1" 400 -
client: (finished: must succeed: push login --issuer https://relay:8443 --client-id flakelet-relay 2>&1, in 2.08 seconds)
client: must succeed: test "$(stat -c %a /root/.local/state/flakelet-push/token.json)" = 600
client: (finished: must succeed: test "$(stat -c %a /root/.local/state/flakelet-push/token.json)" = 600, in 0.01 seconds)
client: must succeed: push --relay https://relay:7443 deploy agent/other 2>&1
agent # [84917.278727] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:38.407937Z","level":"INFO","message":"start","id":"14457d368d0786df7ad554cb3c34c093","flakelet":"other","rule":"admins","relay":"relay","caller":"Some(\"oidc:mock:groups:wheel\\noidc:mock:someone\")","target":"flakelet_relay::agent::conn"}
agent # [84917.279711] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:38.408518Z","level":"INFO","message":"update starting","flakelet":"other","ids":"[\"14457d368d0786df7ad554cb3c34c093\"]","target":"flakelet_relay::agent::jobs"}
agent # [84917.312882] agent systemd[1]: Starting flakelet update other (via relay)...
agent # [84917.346950] agent systemd[1]: Started flakelet update other (via relay).
agent # [84917.352427] agent flakelet[1189]: other: using prebuilt artifact /nix/store/hmr990n0b4v6rpzrcpyyw738r9xi7z95-flakelet-other-v1
agent # [84917.352971] agent flakelet[1189]: other: up to date
agent # [84917.355240] agent systemd[1]: flakelet-relay-job-other.service: Deactivated successfully.
relay # [84917.251357] relay 93sn3sv24fj26ksccpppzwg6kbf10s4w-device-mock[185]: 127.0.0.1 - - [06/Sep/2026 06:14:38] "POST /token HTTP/1.1" 200 -
relay # [84917.278263] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:38.407520Z","level":"INFO","message":"deploy accepted","job":"25218d3e6135daf23480ff25eb424e8b","caller":"oidc:mock:groups:wheel\noidc:mock:someone","targets":"[\"agent/other\"]","target":"flakelet_relay::relay::api"}
client: (finished: must succeed: push --relay https://relay:7443 deploy agent/other 2>&1, in 0.64 seconds)
client: must succeed: push --relay https://relay:7443 deploy agent/other 2>&1
relay # [84917.900836] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:39.030092Z","level":"INFO","message":"deploy finished","job":"25218d3e6135daf23480ff25eb424e8b","ok":true,"target":"flakelet_relay::relay::api"}
relay # [84917.919255] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:39.048499Z","level":"INFO","message":"deploy accepted","job":"822444a1b1309653e979b866219cdf34","caller":"oidc:mock:groups:wheel\noidc:mock:someone","targets":"[\"agent/other\"]","target":"flakelet_relay::relay::api"}
agent # [84917.900304] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:39.029552Z","level":"INFO","message":"update finished","flakelet":"other","status":"Unchanged","generation":"Some(1)","target":"flakelet_relay::agent::jobs"}
agent # [84917.919548] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:39.048786Z","level":"INFO","message":"start","id":"625552199fde351965a3f3909508eea7","flakelet":"other","rule":"admins","relay":"relay","caller":"Some(\"oidc:mock:groups:wheel\\noidc:mock:someone\")","target":"flakelet_relay::agent::conn"}
agent # [84917.919970] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:39.049261Z","level":"INFO","message":"update starting","flakelet":"other","ids":"[\"625552199fde351965a3f3909508eea7\"]","target":"flakelet_relay::agent::jobs"}
agent # [84917.965525] agent systemd[1]: Starting flakelet update other (via relay)...
agent # [84918.001750] agent systemd[1]: Started flakelet update other (via relay).
agent # [84918.006574] agent flakelet[1207]: other: using prebuilt artifact /nix/store/hmr990n0b4v6rpzrcpyyw738r9xi7z95-flakelet-other-v1
agent # [84918.007476] agent flakelet[1207]: other: up to date
agent # [84918.010683] agent systemd[1]: flakelet-relay-job-other.service: Deactivated successfully.
client: (finished: must succeed: push --relay https://relay:7443 deploy agent/other 2>&1, in 0.67 seconds)
(finished: subtest: push login via device flow, cached token used afterwards, in 3.40 seconds)
subtest: waves: failing first wave skips the second
agent: must succeed: jq '.services.app.prebuilt="/nix/store/8282rnbvyk847q4l4zby3zwcq3jpzrvw-flakelet-app-broken"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json
agent: (finished: must succeed: jq '.services.app.prebuilt="/nix/store/8282rnbvyk847q4l4zby3zwcq3jpzrvw-flakelet-app-broken"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json, in 0.01 seconds)
client: must fail: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/app --wave agent/other 2>&1
agent # [84918.569978] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:39.699182Z","level":"INFO","message":"update finished","flakelet":"other","status":"Unchanged","generation":"Some(1)","target":"flakelet_relay::agent::jobs"}
agent # [84918.606817] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:39.736094Z","level":"INFO","message":"start","id":"1f0c84abfe046ab751b69914e8ef2ec0","flakelet":"app","rule":"admins","relay":"relay","caller":"Some(\"x509:email:admin@example.org\")","target":"flakelet_relay::agent::conn"}
agent # [84918.607065] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:39.736361Z","level":"INFO","message":"update starting","flakelet":"app","ids":"[\"1f0c84abfe046ab751b69914e8ef2ec0\"]","target":"flakelet_relay::agent::jobs"}
agent # [84918.660825] agent systemd[1]: Starting flakelet update app (via relay)...
agent # [84918.693881] agent systemd[1]: Started flakelet update app (via relay).
agent # [84918.698415] agent flakelet[1228]: app: using prebuilt artifact /nix/store/8282rnbvyk847q4l4zby3zwcq3jpzrvw-flakelet-app-broken
agent # [84918.699109] agent flakelet[1228]: app: activating generation 4
agent # [84918.713270] agent systemd[1]: Stopping app v1...
agent # [84918.713779] agent systemd[1]: app.service: Deactivated successfully.
agent # [84918.714159] agent systemd[1]: Stopped app v1.
agent # [84918.731901] agent systemd[1]: Reload requested from client PID 1235 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84918.731986] agent systemd[1]: Reloading...
relay # [84918.570925] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:39.700142Z","level":"INFO","message":"deploy finished","job":"822444a1b1309653e979b866219cdf34","ok":true,"target":"flakelet_relay::relay::api"}
relay # [84918.606601] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:39.735861Z","level":"INFO","message":"deploy accepted","job":"233d11327806c6ba4302b8da0bf6b8a9","caller":"x509:email:admin@example.org","targets":"[\"agent/app\", \"agent/other\"]","target":"flakelet_relay::relay::api"}
agent # [84919.080377] agent systemd[1]: Reloading finished in 347 ms.
agent # [84919.168878] agent systemd[1]: Reload requested from client PID 1265 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84919.168936] agent systemd[1]: Reloading...
agent # [84919.506261] agent systemd[1]: Reloading finished in 336 ms.
agent # [84919.592834] agent systemd[1]: Reload requested from client PID 1294 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84919.592933] agent systemd[1]: Reloading...
agent # [84919.931432] agent systemd[1]: Reloading finished in 337 ms.
agent # [84920.020634] agent systemd[1]: Reload requested from client PID 1325 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84920.020686] agent systemd[1]: Reloading...
agent # [84920.361111] agent systemd[1]: Reloading finished in 340 ms.
agent # [84920.445405] agent systemd[1]: Starting app broken...
agent # [84920.477538] agent (nonexistent)[1355]: app.service: Unable to locate executable '/nonexistent': No such file or directory
agent # [84920.477564] agent (nonexistent)[1355]: app.service: Failed at step EXEC spawning /nonexistent: No such file or directory
agent # [84920.478401] agent systemd[1]: app.service: Main process exited, code=exited, status=203/EXEC
agent # [84920.478655] agent systemd[1]: app.service: Failed with result 'exit-code'.
agent # [84920.479271] agent systemd[1]: Failed to start app broken.
agent # [84920.519415] agent systemd[1]: Reload requested from client PID 1362 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84920.519474] agent systemd[1]: Reloading...
agent # [84920.860217] agent systemd[1]: Reloading finished in 340 ms.
agent # [84920.948253] agent systemd[1]: Reload requested from client PID 1392 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84920.948309] agent systemd[1]: Reloading...
agent # [84921.286823] agent systemd[1]: Reloading finished in 338 ms.
agent # [84921.373421] agent systemd[1]: Reload requested from client PID 1422 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84921.373521] agent systemd[1]: Reloading...
agent # [84921.715943] agent systemd[1]: Reloading finished in 341 ms.
agent # [84921.793023] agent systemd[1]: Reload requested from client PID 1452 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84921.793065] agent systemd[1]: Reloading...
agent # [84922.128917] agent systemd[1]: Reloading finished in 335 ms.
agent # [84922.216705] agent systemd[1]: Starting app v1...
agent # [84922.246083] agent systemd[1]: Started app v1.
agent # [84922.246853] agent flakelet[1228]: app: deploy failed, rolled back: systemctl start app.service failed:
agent # [84922.246853] agent flakelet[1228]: failed units: app.service. See journalctl -u app.service
agent # [84922.248970] agent systemd[1]: flakelet-relay-job-app.service: Main process exited, code=exited, status=1/FAILURE
agent # [84922.249090] agent systemd[1]: flakelet-relay-job-app.service: Failed with result 'exit-code'.
client: (finished: must fail: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/app --wave agent/other 2>&1, in 4.36 seconds)
agent: must succeed: systemctl show app.service -p Description | grep -q 'app v1'
agent: (finished: must succeed: systemctl show app.service -p Description | grep -q 'app v1', in 0.01 seconds)
(finished: subtest: waves: failing first wave skips the second, in 4.38 seconds)
subtest: detach returns once the job is accepted
agent: must succeed: jq '.services.app.prebuilt="/nix/store/ln47rsd5km8a04hd5zlkz4q1v352zqh3-flakelet-app-slow2"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json
agent: (finished: must succeed: jq '.services.app.prebuilt="/nix/store/ln47rsd5km8a04hd5zlkz4q1v352zqh3-flakelet-app-slow2"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json, in 0.01 seconds)
client: must succeed: timeout 20 push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy --detach agent/app 2>&1
client: (finished: must succeed: timeout 20 push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy --detach agent/app 2>&1, in 0.02 seconds)
agent: waiting for success: systemctl is-active flakelet-relay-job-app.service
relay # [84922.940893] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:44.070074Z","level":"INFO","message":"deploy finished","job":"233d11327806c6ba4302b8da0bf6b8a9","ok":false,"target":"flakelet_relay::relay::api"}
relay # [84922.989791] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:44.119062Z","level":"INFO","message":"deploy accepted","job":"f0ef0f172dadfeb757f8028afc7ad84d","caller":"x509:email:admin@example.org","targets":"[\"agent/app\"]","target":"flakelet_relay::relay::api"}
agent # [84922.940012] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:44.069199Z","level":"INFO","message":"update finished","flakelet":"app","status":"RolledBack","generation":"Some(3)","target":"flakelet_relay::agent::jobs"}
agent # [84922.990053] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:44.119251Z","level":"INFO","message":"start","id":"24727bc93796d2bbe431b12b80c8febe","flakelet":"app","rule":"admins","relay":"relay","caller":"Some(\"x509:email:admin@example.org\")","target":"flakelet_relay::agent::conn"}
agent # [84922.990259] agent flakelet-agent[304]: {"timestamp":"2026-09-06T06:14:44.119559Z","level":"INFO","message":"update starting","flakelet":"app","ids":"[\"24727bc93796d2bbe431b12b80c8febe\"]","target":"flakelet_relay::agent::jobs"}
agent # [84923.043345] agent systemd[1]: Starting flakelet update app (via relay)...
agent # [84923.074349] agent systemd[1]: Started flakelet update app (via relay).
agent # [84923.079249] agent flakelet[1507]: app: using prebuilt artifact /nix/store/ln47rsd5km8a04hd5zlkz4q1v352zqh3-flakelet-app-slow2
agent # [84923.079893] agent flakelet[1507]: app: activating generation 4
agent # [84923.095029] agent systemd[1]: Stopping app v1...
agent # [84923.095541] agent systemd[1]: app.service: Deactivated successfully.
agent # [84923.095899] agent systemd[1]: Stopped app v1.
agent # [84923.112627] agent systemd[1]: Reload requested from client PID 1514 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84923.112670] agent systemd[1]: Reloading...
agent # [84923.454122] agent systemd[1]: Reloading finished in 341 ms.
agent # [84923.542375] agent systemd[1]: Reload requested from client PID 1544 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84923.542447] agent systemd[1]: Reloading...
agent # [84923.880717] agent systemd[1]: Reloading finished in 337 ms.
agent # [84923.972201] agent systemd[1]: Reload requested from client PID 1573 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84923.972259] agent systemd[1]: Reloading...
agent # [84924.313348] agent systemd[1]: Reloading finished in 340 ms.
agent: (finished: waiting for success: systemctl is-active flakelet-relay-job-app.service, in 1.40 seconds)
??? Warning (UserWarning): wait_until_fails(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/fv4yr9c0f9kyrfc00100i4rlshiiidbd-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
agent: waiting for failure: systemctl is-active flakelet-relay-job-app.service
??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/fv4yr9c0f9kyrfc00100i4rlshiiidbd-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
agent # [84924.394553] agent systemd[1]: Reload requested from client PID 1605 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84924.394605] agent systemd[1]: Reloading...
agent # [84924.732794] agent systemd[1]: Reloading finished in 337 ms.
agent # [84924.824093] agent systemd[1]: Starting app slow2...
agent # [84930.912763] agent systemd[1]: Started app slow2.
agent # [84930.936839] agent flakelet[1507]: app: updated to generation 4
agent # [84930.940166] agent systemd[1]: flakelet-relay-job-app.service: Deactivated successfully.
agent: (finished: waiting for failure: systemctl is-active flakelet-relay-job-app.service, in 7.52 seconds)
(finished: subtest: detach returns once the job is accepted, in 8.95 seconds)
subtest: unknown host is final, missing agent is retried, agents listing
client: must fail: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy nope/app 2>&1
client: (finished: must fail: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy nope/app 2>&1, in 0.02 seconds)
agent: must succeed: systemctl stop flakelet-agent
agent: (finished: must succeed: systemctl stop flakelet-agent, in 0.03 seconds)
relay: waiting for success: curl -sf http://127.0.0.1:7400/metrics | grep -q 'agent_up{host="agent"} 0'
relay: (finished: waiting for success: curl -sf http://127.0.0.1:7400/metrics | grep -q 'agent_up{host="agent"} 0', in 0.02 seconds)
client: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/other > /tmp/retry.out 2>&1 &
client: (finished: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/other > /tmp/retry.out 2>&1 &, in 0.01 seconds)
client: waiting for success: grep -q 'agent_unavailable.*retrying' /tmp/retry.out
relay # [84931.937088] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:53.066355Z","level":"INFO","message":"agent disconnected: websocket closed","host":"agent","target":"flakelet_relay::relay::agent_conn"}
agent # [84931.937201] agent systemd[1]: Stopping flakelet-agent...
agent # [84931.957139] agent systemd[1]: flakelet-agent.service: Deactivated successfully.
agent # [84931.957804] agent systemd[1]: Stopped flakelet-agent.
client: (finished: waiting for success: grep -q 'agent_unavailable.*retrying' /tmp/retry.out, in 1.02 seconds)
agent: must succeed: systemctl start flakelet-agent
agent: (finished: must succeed: systemctl start flakelet-agent, in 0.07 seconds)
??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/fv4yr9c0f9kyrfc00100i4rlshiiidbd-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
client: waiting for success: grep -q 'agent/other: unchanged' /tmp/retry.out
agent # [84933.016695] agent systemd[1]: Starting flakelet-agent...
agent # [84933.071795] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:14:54.201056Z","level":"INFO","message":"reattaching to running unit","flakelet":"app","ids":"[\"24727bc93796d2bbe431b12b80c8febe\"]","target":"flakelet_relay::agent::jobs"}
agent # [84933.071972] agent systemd[1]: Started flakelet-agent.
agent # [84933.170393] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:14:54.299626Z","level":"INFO","message":"connected","relay":"https://relay:7443","relay_name":"relay","relay_version":"0.1.0","host":"agent","target":"flakelet_relay::agent::conn"}
relay # [84933.170461] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:54.299689Z","level":"INFO","message":"agent connected","host":"agent","version":"0.1.0","flakelets":"[Named { name: \"app\", generation: Some(4), revision: Some(\"prebuilt:app\") }, Named { name: \"other\", generation: Some(1), revision: Some(\"prebuilt:other\") }]","target":"flakelet_relay::relay::agent_conn"}
agent # [84933.633488] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:14:54.762710Z","level":"INFO","message":"update finished","flakelet":"app","status":"Updated","generation":"Some(4)","target":"flakelet_relay::agent::jobs"}
agent # [84935.005305] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:14:56.134515Z","level":"INFO","message":"start","id":"341a24f36eee22891cac419dfdd39181","flakelet":"other","rule":"admins","relay":"relay","caller":"Some(\"x509:email:admin@example.org\")","target":"flakelet_relay::agent::conn"}
agent # [84935.006270] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:14:56.135113Z","level":"INFO","message":"update starting","flakelet":"other","ids":"[\"341a24f36eee22891cac419dfdd39181\"]","target":"flakelet_relay::agent::jobs"}
agent # [84935.065062] agent systemd[1]: Starting flakelet update other (via relay)...
agent # [84935.100420] agent systemd[1]: Started flakelet update other (via relay).
agent # [84935.105940] agent flakelet[2073]: other: using prebuilt artifact /nix/store/hmr990n0b4v6rpzrcpyyw738r9xi7z95-flakelet-other-v1
agent # [84935.106766] agent flakelet[2073]: other: up to date
agent # [84935.109037] agent systemd[1]: flakelet-relay-job-other.service: Deactivated successfully.
relay # [84935.005034] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:56.134248Z","level":"INFO","message":"deploy accepted","job":"37114be9c0062fbf49e54771d81fad12","caller":"x509:email:admin@example.org","targets":"[\"agent/other\"]","target":"flakelet_relay::relay::api"}
relay # [84935.660993] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:56.790264Z","level":"INFO","message":"deploy finished","job":"37114be9c0062fbf49e54771d81fad12","ok":true,"target":"flakelet_relay::relay::api"}
client: (finished: waiting for success: grep -q 'agent/other: unchanged' /tmp/retry.out, in 3.05 seconds)
client: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem agents
agent # [84935.660276] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:14:56.789527Z","level":"INFO","message":"update finished","flakelet":"other","status":"Unchanged","generation":"Some(1)","target":"flakelet_relay::agent::jobs"}
client: (finished: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem agents, in 0.02 seconds)
client: must succeed: echo '{"groups": []}' | step crypto jwt sign --key /nix/store/r7sclamg09v434w8zjlfnrcrn1w79wh6-flakelet-relay-test-issuer/jwk.json --iss https://relay:8443 --aud flakelet-relay --sub 'repo:github:example/app:ref:refs/heads/main' --exp $(( $(date +%s) + 300 )) --jti $(head -c8 /dev/urandom | base32)
client: (finished: must succeed: echo '{"groups": []}' | step crypto jwt sign --key /nix/store/r7sclamg09v434w8zjlfnrcrn1w79wh6-flakelet-relay-test-issuer/jwk.json --iss https://relay:8443 --aud flakelet-relay --sub 'repo:github:example/app:ref:refs/heads/main' --exp $(( $(date +%s) + 300 )) --jti $(head -c8 /dev/urandom | base32), in 0.05 seconds)
client: must succeed: FLAKELET_RELAY_TOKEN_COMMAND='echo eyJhbGciOiJFZERTQSIsImtpZCI6ImsxIiwidHlwIjoiSldUIn0.eyJhdWQiOiJmbGFrZWxldC1yZWxheSIsImV4cCI6MTc4ODY3NTU5NywiZ3JvdXBzIjpbXSwiaWF0IjoxNzg4Njc1Mjk3LCJpc3MiOiJodHRwczovL3JlbGF5Ojg0NDMiLCJqdGkiOiJBREJLVE03S0tLUFlNPT09IiwibmJmIjoxNzg4Njc1Mjk3LCJzdWIiOiJyZXBvOmdpdGh1YjpleGFtcGxlL2FwcDpyZWY6cmVmcy9oZWFkcy9tYWluIn0.zlGRHorh3UEfTilEPwHEbrVQVf__7AxnM_oH1QEKJ8Wq3-DbPQNsbeyynoj-qQemCL0NjJIb6drtxNzUOaSWCg' push --relay https://relay:7443 agents
client: (finished: must succeed: FLAKELET_RELAY_TOKEN_COMMAND='echo eyJhbGciOiJFZERTQSIsImtpZCI6ImsxIiwidHlwIjoiSldUIn0.eyJhdWQiOiJmbGFrZWxldC1yZWxheSIsImV4cCI6MTc4ODY3NTU5NywiZ3JvdXBzIjpbXSwiaWF0IjoxNzg4Njc1Mjk3LCJpc3MiOiJodHRwczovL3JlbGF5Ojg0NDMiLCJqdGkiOiJBREJLVE03S0tLUFlNPT09IiwibmJmIjoxNzg4Njc1Mjk3LCJzdWIiOiJyZXBvOmdpdGh1YjpleGFtcGxlL2FwcDpyZWY6cmVmcy9oZWFkcy9tYWluIn0.zlGRHorh3UEfTilEPwHEbrVQVf__7AxnM_oH1QEKJ8Wq3-DbPQNsbeyynoj-qQemCL0NjJIb6drtxNzUOaSWCg' push --relay https://relay:7443 agents, in 0.02 seconds)
(finished: subtest: unknown host is final, missing agent is retried, agents listing, in 4.30 seconds)
subtest: certificate not listed under agents cannot connect as agent
client: must succeed: curl -s -o /dev/null -w '%{http_code}' --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/mallory/cert.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/mallory/key.pem -H 'Upgrade: websocket' -H 'Connection: Upgrade' -H 'Sec-WebSocket-Version: 13' -H 'Sec-WebSocket-Key: dGhlIHNhbXBsZSBub25jZQ==' https://relay:7443/v1/agent
client: (finished: must succeed: curl -s -o /dev/null -w '%{http_code}' --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/mallory/cert.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/mallory/key.pem -H 'Upgrade: websocket' -H 'Connection: Upgrade' -H 'Sec-WebSocket-Version: 13' -H 'Sec-WebSocket-Key: dGhlIHNhbXBsZSBub25jZQ==' https://relay:7443/v1/agent, in 0.02 seconds)
(finished: subtest: certificate not listed under agents cannot connect as agent, in 0.02 seconds)
subtest: metrics
relay: must succeed: curl -sf http://127.0.0.1:7400/metrics
relay: (finished: must succeed: curl -sf http://127.0.0.1:7400/metrics, in 0.02 seconds)
(finished: subtest: metrics, in 0.02 seconds)
subtest: agent link drop mid-run replays missed lines once
agent: must succeed: jq '.services.app.prebuilt="/nix/store/c67jj8kx3m50nyj874aqmdqf21w5iznd-flakelet-app-slow"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json
agent: (finished: must succeed: jq '.services.app.prebuilt="/nix/store/c67jj8kx3m50nyj874aqmdqf21w5iznd-flakelet-app-slow"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json, in 0.01 seconds)
agent: must succeed: date +%s
agent: (finished: must succeed: date +%s, in 0.01 seconds)
client: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/app > /tmp/slow.out 2>&1 &
client: (finished: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/app > /tmp/slow.out 2>&1 &, in 0.01 seconds)
agent: waiting for success: journalctl -u flakelet-relay-job-app.service --since=@1788675297 | grep -q 'app-slow'
agent # [84936.286568] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:14:57.415808Z","level":"INFO","message":"start","id":"7a94d5587e6f543e3c1b2fcac4d90fd6","flakelet":"app","rule":"admins","relay":"relay","caller":"Some(\"x509:email:admin@example.org\")","target":"flakelet_relay::agent::conn"}
agent # [84936.287157] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:14:57.416394Z","level":"INFO","message":"update starting","flakelet":"app","ids":"[\"7a94d5587e6f543e3c1b2fcac4d90fd6\"]","target":"flakelet_relay::agent::jobs"}
agent # [84936.349979] agent systemd[1]: Starting flakelet update app (via relay)...
agent # [84936.384082] agent systemd[1]: Started flakelet update app (via relay).
agent # [84936.389545] agent flakelet[2098]: app: using prebuilt artifact /nix/store/c67jj8kx3m50nyj874aqmdqf21w5iznd-flakelet-app-slow
agent # [84936.390286] agent flakelet[2098]: app: activating generation 5
agent # [84936.406632] agent systemd[1]: Stopping app slow2...
agent # [84936.407185] agent systemd[1]: app.service: Deactivated successfully.
agent # [84936.407576] agent systemd[1]: Stopped app slow2.
agent # [84936.430502] agent systemd[1]: Reload requested from client PID 2105 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84936.430596] agent systemd[1]: Reloading...
relay # [84936.226326] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:57.355592Z","level":"INFO","message":"agent rejected: no agents entry matches","principals":"[\"x509:dns:mallory\"]","target":"flakelet_relay::relay::agent_conn"}
relay # [84936.286179] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:57.415393Z","level":"INFO","message":"deploy accepted","job":"1ec5f3b6d0fcfa69c747402c5d67d6e5","caller":"x509:email:admin@example.org","targets":"[\"agent/app\"]","target":"flakelet_relay::relay::api"}
agent # [84936.811995] agent systemd[1]: Reloading finished in 380 ms.
agent # [84936.901052] agent systemd[1]: Reload requested from client PID 2135 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84936.901100] agent systemd[1]: Reloading...
agent: (finished: waiting for success: journalctl -u flakelet-relay-job-app.service --since=@1788675297 | grep -q 'app-slow', in 1.02 seconds)
agent: must succeed: for a in $(getent ahosts relay | cut -d' ' -f1 | sort -u); do ip route add unreachable $a; done
agent: (finished: must succeed: for a in $(getent ahosts relay | cut -d' ' -f1 | sort -u); do ip route add unreachable $a; done, in 0.02 seconds)
relay: must succeed: for a in $(getent ahosts agent | cut -d' ' -f1 | sort -u); do ss -K dst "[$a]"; done
relay: (finished: must succeed: for a in $(getent ahosts agent | cut -d' ' -f1 | sort -u); do ss -K dst "[$a]"; done, in 0.06 seconds)
agent: must succeed: ss -K dport = 7443
agent: (finished: must succeed: ss -K dport = 7443, in 0.03 seconds)
agent: waiting for success: journalctl -u flakelet-relay-job-app.service --since=@1788675297 | grep -q 'updated to generation'
agent # [84937.268833] agent systemd[1]: Reloading finished in 367 ms.
agent # [84937.351574] agent systemd[1]: Reload requested from client PID 2174 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84937.351620] agent systemd[1]: Reloading...
agent # [84937.397141] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:14:58.526394Z","level":"INFO","message":"disconnected: Software caused connection abort (os error 103)","relay":"https://relay:7443","target":"flakelet_relay::agent::conn"}
relay # [84937.366564] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:14:58.495771Z","level":"INFO","message":"agent disconnected: Software caused connection abort (os error 103)","host":"agent","target":"flakelet_relay::relay::agent_conn"}
agent # [84937.697606] agent systemd[1]: Reloading finished in 345 ms.
agent # [84937.787986] agent systemd[1]: Reload requested from client PID 2209 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84937.788037] agent systemd[1]: Reloading...
agent # [84938.131774] agent systemd[1]: Reloading finished in 343 ms.
agent # [84938.224466] agent systemd[1]: Starting app slow...
agent # [84938.490272] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:14:59.619430Z","level":"WARN","message":"connect failed: connect relay:7443: No route to host (os error 113)","relay":"https://relay:7443","target":"flakelet_relay::agent::conn"}
agent # [84940.568161] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:15:01.697416Z","level":"WARN","message":"connect failed: connect relay:7443: No route to host (os error 113)","relay":"https://relay:7443","target":"flakelet_relay::agent::conn"}
agent: (finished: waiting for success: journalctl -u flakelet-relay-job-app.service --since=@1788675297 | grep -q 'updated to generation', in 7.09 seconds)
agent: must succeed: for a in $(getent ahosts relay | cut -d' ' -f1 | sort -u); do ip route del unreachable $a; done
agent: (finished: must succeed: for a in $(getent ahosts relay | cut -d' ' -f1 | sort -u); do ip route del unreachable $a; done, in 0.02 seconds)
client: waiting for success: grep -q 'agent/app: updated' /tmp/slow.out
agent # [84944.295555] agent systemd[1]: Started app slow.
agent # [84944.311975] agent flakelet[2098]: app: updated to generation 5
agent # [84944.312934] agent systemd[1]: flakelet-relay-job-app.service: Deactivated successfully.
relay # [84944.654166] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:15:05.783403Z","level":"INFO","message":"agent connected","host":"agent","version":"0.1.0","flakelets":"[Named { name: \"app\", generation: Some(5), revision: Some(\"prebuilt:app\") }, Named { name: \"other\", generation: Some(1), revision: Some(\"prebuilt:other\") }]","target":"flakelet_relay::relay::agent_conn"}
agent # [84944.654102] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:15:05.783339Z","level":"INFO","message":"connected","relay":"https://relay:7443","relay_name":"relay","relay_version":"0.1.0","host":"agent","target":"flakelet_relay::agent::conn"}
agent # [84944.655290] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:15:05.784583Z","level":"INFO","message":"start","id":"7a94d5587e6f543e3c1b2fcac4d90fd6","flakelet":"app","rule":"admins","relay":"relay","caller":"Some(\"x509:email:admin@example.org\")","target":"flakelet_relay::agent::conn"}
client: (finished: waiting for success: grep -q 'agent/app: updated' /tmp/slow.out, in 1.02 seconds)
client: must succeed: cat /tmp/slow.out
client: (finished: must succeed: cat /tmp/slow.out, in 0.01 seconds)
(finished: subtest: agent link drop mid-run replays missed lines once, in 9.29 seconds)
subtest: agent restart mid-run reattaches to the unit
agent: must succeed: jq '.services.app.prebuilt="/nix/store/ln47rsd5km8a04hd5zlkz4q1v352zqh3-flakelet-app-slow2"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json
agent: (finished: must succeed: jq '.services.app.prebuilt="/nix/store/ln47rsd5km8a04hd5zlkz4q1v352zqh3-flakelet-app-slow2"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json, in 0.01 seconds)
client: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/app > /tmp/restart.out 2>&1 &
client: (finished: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/app > /tmp/restart.out 2>&1 &, in 0.01 seconds)
agent: waiting for success: journalctl -u flakelet-relay-job-app.service --since -20s | grep -q 'app-slow2'
agent # [84945.386387] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:15:06.515602Z","level":"INFO","message":"update finished","flakelet":"app","status":"Updated","generation":"Some(5)","target":"flakelet_relay::agent::jobs"}
agent # [84945.570399] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:15:06.699611Z","level":"INFO","message":"start","id":"9d04c88ad4f512fa4f82c5100d18fc16","flakelet":"app","rule":"admins","relay":"relay","caller":"Some(\"x509:email:admin@example.org\")","target":"flakelet_relay::agent::conn"}
agent # [84945.570977] agent flakelet-agent[1660]: {"timestamp":"2026-09-06T06:15:06.700246Z","level":"INFO","message":"update starting","flakelet":"app","ids":"[\"9d04c88ad4f512fa4f82c5100d18fc16\"]","target":"flakelet_relay::agent::jobs"}
agent # [84945.633762] agent systemd[1]: Starting flakelet update app (via relay)...
relay # [84945.387136] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:15:06.516378Z","level":"INFO","message":"deploy finished","job":"1ec5f3b6d0fcfa69c747402c5d67d6e5","ok":true,"target":"flakelet_relay::relay::api"}
relay # [84945.569938] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:15:06.699197Z","level":"INFO","message":"deploy accepted","job":"9c34d306b5e457f2f406e05a8fbb7e1f","caller":"x509:email:admin@example.org","targets":"[\"agent/app\"]","target":"flakelet_relay::relay::api"}
agent # [84945.641578] agent systemd[1]: Started flakelet update app (via relay).
agent # [84945.645323] agent flakelet[2330]: app: using prebuilt artifact /nix/store/ln47rsd5km8a04hd5zlkz4q1v352zqh3-flakelet-app-slow2
agent # [84945.646246] agent flakelet[2330]: app: activating generation 6
agent # [84945.660062] agent systemd[1]: Stopping app slow...
agent # [84945.661805] agent systemd[1]: app.service: Deactivated successfully.
agent # [84945.662226] agent systemd[1]: Stopped app slow.
agent # [84945.673782] agent systemd[1]: Reload requested from client PID 2337 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84945.673823] agent systemd[1]: Reloading...
agent # [84946.064258] agent systemd[1]: Reloading finished in 390 ms.
agent # [84946.162236] agent systemd[1]: Reload requested from client PID 2367 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84946.162337] agent systemd[1]: Reloading...
agent: (finished: waiting for success: journalctl -u flakelet-relay-job-app.service --since -20s | grep -q 'app-slow2', in 1.03 seconds)
agent: must succeed: systemctl restart flakelet-agent
agent # [84946.664344] agent systemd[1]: Reloading finished in 501 ms.
agent # [84946.764537] agent systemd[1]: Reload requested from client PID 2401 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84946.764585] agent systemd[1]: Reloading...
agent # [84947.148375] agent systemd[1]: Reloading finished in 383 ms.
agent # [84947.238071] agent systemd[1]: Stopping flakelet-agent...
agent # [84947.247123] agent systemd[1]: Reload requested from client PID 2431 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84947.247164] agent systemd[1]: Reloading...
agent # [84947.602463] agent systemd[1]: Reloading finished in 354 ms.
relay # [84947.238378] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:15:08.367580Z","level":"INFO","message":"agent disconnected: websocket closed","host":"agent","target":"flakelet_relay::relay::agent_conn"}
agent: (finished: must succeed: systemctl restart flakelet-agent, in 1.17 seconds)
agent: must succeed: test -n "$(ls /var/lib/flakelet-agent/jobs)"
agent: (finished: must succeed: test -n "$(ls /var/lib/flakelet-agent/jobs)", in 0.01 seconds)
client: waiting for success: grep -q 'agent/app: updated' /tmp/restart.out
agent # [84947.681340] agent systemd[1]: flakelet-agent.service: Deactivated successfully.
agent # [84947.681610] agent systemd[1]: Stopped flakelet-agent.
agent # [84947.687443] agent systemd[1]: Starting flakelet-agent...
agent # [84947.688849] agent systemd[1]: Starting app slow2...
agent # [84947.753711] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:08.882920Z","level":"INFO","message":"reattaching to running unit","flakelet":"app","ids":"[\"9d04c88ad4f512fa4f82c5100d18fc16\"]","target":"flakelet_relay::agent::jobs"}
agent # [84947.753772] agent systemd[1]: Started flakelet-agent.
agent # [84947.836197] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:08.965461Z","level":"INFO","message":"connected","relay":"https://relay:7443","relay_name":"relay","relay_version":"0.1.0","host":"agent","target":"flakelet_relay::agent::conn"}
agent # [84947.836376] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:08.965561Z","level":"INFO","message":"start","id":"9d04c88ad4f512fa4f82c5100d18fc16","flakelet":"app","rule":"admins","relay":"relay","caller":"Some(\"x509:email:admin@example.org\")","target":"flakelet_relay::agent::conn"}
relay # [84947.836236] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:15:08.965494Z","level":"INFO","message":"agent connected","host":"agent","version":"0.1.0","flakelets":"[Named { name: \"app\", generation: Some(5), revision: Some(\"prebuilt:app\") }, Named { name: \"other\", generation: Some(1), revision: Some(\"prebuilt:other\") }]","target":"flakelet_relay::relay::agent_conn"}
agent # [84953.756111] agent systemd[1]: Started app slow2.
agent # [84953.775326] agent flakelet[2330]: app: updated to generation 6
agent # [84953.777629] agent systemd[1]: flakelet-relay-job-app.service: Deactivated successfully.
agent # [84954.342454] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:15.471684Z","level":"INFO","message":"update finished","flakelet":"app","status":"Updated","generation":"Some(6)","target":"flakelet_relay::agent::jobs"}
relay # [84954.343329] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:15:15.472531Z","level":"INFO","message":"deploy finished","job":"9c34d306b5e457f2f406e05a8fbb7e1f","ok":true,"target":"flakelet_relay::relay::api"}
client: (finished: waiting for success: grep -q 'agent/app: updated' /tmp/restart.out, in 7.08 seconds)
client: must succeed: cat /tmp/restart.out
client: (finished: must succeed: cat /tmp/restart.out, in 0.01 seconds)
agent: must succeed: systemctl is-active app.service
agent: (finished: must succeed: systemctl is-active app.service, in 0.01 seconds)
(finished: subtest: agent restart mid-run reattaches to the unit, in 9.33 seconds)
subtest: relay restart mid-run, push resumes via /v1/jobs
agent: must succeed: jq '.services.app.prebuilt="/nix/store/c67jj8kx3m50nyj874aqmdqf21w5iznd-flakelet-app-slow"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json
agent: (finished: must succeed: jq '.services.app.prebuilt="/nix/store/c67jj8kx3m50nyj874aqmdqf21w5iznd-flakelet-app-slow"' /etc/flakelet/config.json > /tmp/config.json && cp --remove-destination /tmp/config.json /etc/flakelet/config.json, in 0.01 seconds)
agent: must succeed: date +%s
agent: (finished: must succeed: date +%s, in 0.01 seconds)
client: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/app > /tmp/resume.out 2>&1 &
client: (finished: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy agent/app > /tmp/resume.out 2>&1 &, in 0.01 seconds)
agent: waiting for success: journalctl -u flakelet-relay-job-app.service --since=@1788675316 | grep -q 'app-slow'
agent # [84954.914584] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:16.043809Z","level":"INFO","message":"start","id":"6c5fb2032d298fc6f8a54a82f99273a2","flakelet":"app","rule":"admins","relay":"relay","caller":"Some(\"x509:email:admin@example.org\")","target":"flakelet_relay::agent::conn"}
relay # [84954.914228] relay flakelet-relay[400]: {"timestamp":"2026-09-06T06:15:16.043389Z","level":"INFO","message":"deploy accepted","job":"c46a149e7623dfbfd5aecd8bb1d94a27","caller":"x509:email:admin@example.org","targets":"[\"agent/app\"]","target":"flakelet_relay::relay::api"}
agent # [84954.915115] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:16.044406Z","level":"INFO","message":"update starting","flakelet":"app","ids":"[\"6c5fb2032d298fc6f8a54a82f99273a2\"]","target":"flakelet_relay::agent::jobs"}
agent # [84954.975782] agent systemd[1]: Starting flakelet update app (via relay)...
agent # [84954.984070] agent systemd[1]: Started flakelet update app (via relay).
agent # [84954.988817] agent flakelet[2897]: app: using prebuilt artifact /nix/store/c67jj8kx3m50nyj874aqmdqf21w5iznd-flakelet-app-slow
agent # [84954.989520] agent flakelet[2897]: app: activating generation 7
agent # [84955.002783] agent systemd[1]: Stopping app slow2...
agent # [84955.003700] agent systemd[1]: app.service: Deactivated successfully.
agent # [84955.003892] agent systemd[1]: Stopped app slow2.
agent # [84955.016477] agent systemd[1]: Reload requested from client PID 2904 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84955.016569] agent systemd[1]: Reloading...
agent # [84955.491591] agent systemd[1]: Reloading finished in 474 ms.
agent # [84955.579613] agent systemd[1]: Reload requested from client PID 2934 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84955.579669] agent systemd[1]: Reloading...
agent: (finished: waiting for success: journalctl -u flakelet-relay-job-app.service --since=@1788675316 | grep -q 'app-slow', in 1.02 seconds)
relay: must succeed: systemctl restart flakelet-relay
relay # [84955.933851] relay systemd[1]: Stopping flakelet-relay...
relay # [84955.964925] relay systemd[1]: flakelet-relay.service: Deactivated successfully.
relay # [84955.965334] relay systemd[1]: Stopped flakelet-relay.
relay # [84955.965355] relay systemd[1]: flakelet-relay.service: Consumed 2.173s CPU time over 52.424s wall clock time.
relay # [84955.984527] relay systemd[1]: Starting flakelet-relay...
agent # [84955.934262] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:17.063504Z","level":"INFO","message":"disconnected: websocket closed","relay":"https://relay:7443","target":"flakelet_relay::agent::conn"}
agent # [84956.163696] agent systemd[1]: Reloading finished in 583 ms.
agent # [84956.272418] agent systemd[1]: Reload requested from client PID 2967 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84956.272462] agent systemd[1]: Reloading...
agent # [84956.707168] agent systemd[1]: Reloading finished in 434 ms.
agent # [84956.812105] agent systemd[1]: Reload requested from client PID 2997 ('systemctl') (unit flakelet-relay-job-app.service)...
agent # [84956.812146] agent systemd[1]: Reloading...
agent # [84957.218486] agent systemd[1]: Reloading finished in 405 ms.
agent # [84957.311143] agent systemd[1]: Starting app slow...
agent # [84957.376183] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:18.505432Z","level":"WARN","message":"connect failed: connect relay:7443: Connection refused (os error 111)","relay":"https://relay:7443","target":"flakelet_relay::agent::conn"}
relay: (finished: must succeed: systemctl restart flakelet-relay, in 2.53 seconds)
client: waiting for success: grep -q '» ok' /tmp/resume.out
relay # [84958.450241] relay flakelet-relay[933]: {"timestamp":"2026-09-06T06:15:19.579483Z","level":"INFO","message":"listening on 127.0.0.1:7400","target":"flakelet_relay::relay::server"}
relay # [84958.451098] relay flakelet-relay[933]: {"timestamp":"2026-09-06T06:15:19.579896Z","level":"INFO","message":"listening on [::]:7443","target":"flakelet_relay::relay::server"}
relay # [84958.450827] relay systemd[1]: Started flakelet-relay.
agent # [84959.469222] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:20.598467Z","level":"INFO","message":"connected","relay":"https://relay:7443","relay_name":"relay","relay_version":"0.1.0","host":"agent","target":"flakelet_relay::agent::conn"}
relay # [84959.469298] relay flakelet-relay[933]: {"timestamp":"2026-09-06T06:15:20.598545Z","level":"INFO","message":"agent connected","host":"agent","version":"0.1.0","flakelets":"[Named { name: \"app\", generation: Some(6), revision: Some(\"prebuilt:app\") }, Named { name: \"other\", generation: Some(1), revision: Some(\"prebuilt:other\") }]","target":"flakelet_relay::relay::agent_conn"}
relay # [84962.953553] relay flakelet-relay[933]: {"timestamp":"2026-09-06T06:15:24.082804Z","level":"INFO","message":"job reattached","job":"c46a149e7623dfbfd5aecd8bb1d94a27","targets":"[\"agent/app\"]","target":"flakelet_relay::relay::api"}
agent # [84963.354363] agent systemd[1]: Started app slow.
agent # [84963.376430] agent flakelet[2897]: app: updated to generation 7
agent # [84963.380247] agent systemd[1]: flakelet-relay-job-app.service: Deactivated successfully.
client: (finished: waiting for success: grep -q '» ok' /tmp/resume.out, in 6.07 seconds)
client: must succeed: cat /tmp/resume.out
client: (finished: must succeed: cat /tmp/resume.out, in 0.01 seconds)
(finished: subtest: relay restart mid-run, push resumes via /v1/jobs, in 9.66 seconds)
subtest: job history comes from the agents and survives a relay restart
client: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy --id hist1 agent/other 2>&1
relay # [84964.552031] relay flakelet-relay[933]: {"timestamp":"2026-09-06T06:15:25.681241Z","level":"INFO","message":"deploy accepted","job":"188b06c4636b65849b3ba8daac22dc7c","caller":"x509:email:admin@example.org","targets":"[\"agent/other\"]","target":"flakelet_relay::relay::api"}
agent # [84964.418314] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:25.547562Z","level":"INFO","message":"update finished","flakelet":"app","status":"Updated","generation":"Some(7)","target":"flakelet_relay::agent::jobs"}
agent # [84964.552481] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:25.681728Z","level":"INFO","message":"start","id":"5be20c693e5c0b60e3f85779794dfb86","flakelet":"other","rule":"admins","relay":"relay","caller":"Some(\"x509:email:admin@example.org\")","target":"flakelet_relay::agent::conn"}
agent # [84964.552937] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:25.682210Z","level":"INFO","message":"update starting","flakelet":"other","ids":"[\"5be20c693e5c0b60e3f85779794dfb86\"]","target":"flakelet_relay::agent::jobs"}
agent # [84964.613816] agent systemd[1]: Starting flakelet update other (via relay)...
agent # [84964.621686] agent systemd[1]: Started flakelet update other (via relay).
agent # [84964.625423] agent flakelet[3074]: other: using prebuilt artifact /nix/store/hmr990n0b4v6rpzrcpyyw738r9xi7z95-flakelet-other-v1
agent # [84964.626012] agent flakelet[3074]: other: up to date
agent # [84964.630877] agent systemd[1]: flakelet-relay-job-other.service: Deactivated successfully.
client: (finished: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy --id hist1 agent/other 2>&1, in 0.66 seconds)
relay: must succeed: systemctl restart flakelet-relay
relay # [84965.188612] relay flakelet-relay[933]: {"timestamp":"2026-09-06T06:15:26.317835Z","level":"INFO","message":"deploy finished","job":"188b06c4636b65849b3ba8daac22dc7c","ok":true,"target":"flakelet_relay::relay::api"}
relay # [84965.205103] relay systemd[1]: Stopping flakelet-relay...
relay # [84965.254869] relay systemd[1]: flakelet-relay.service: Deactivated successfully.
relay # [84965.255421] relay systemd[1]: Stopped flakelet-relay.
relay # [84965.255466] relay systemd[1]: flakelet-relay.service: Consumed 2.064s CPU time over 9.270s wall clock time.
relay # [84965.294043] relay systemd[1]: Starting flakelet-relay...
agent # [84965.187790] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:26.317006Z","level":"INFO","message":"update finished","flakelet":"other","status":"Unchanged","generation":"Some(1)","target":"flakelet_relay::agent::jobs"}
agent # [84965.205316] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:26.334590Z","level":"INFO","message":"disconnected: websocket closed","relay":"https://relay:7443","target":"flakelet_relay::agent::conn"}
agent # [84966.293588] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:27.422846Z","level":"WARN","message":"connect failed: connect relay:7443: Connection refused (os error 111)","relay":"https://relay:7443","target":"flakelet_relay::agent::conn"}
relay: (finished: must succeed: systemctl restart flakelet-relay, in 2.62 seconds)
relay: waiting for success: curl -sf http://127.0.0.1:7400/metrics | grep -q 'agent_up{host="agent"} 1'
relay # [84967.808445] relay flakelet-relay[1323]: {"timestamp":"2026-09-06T06:15:28.937654Z","level":"INFO","message":"listening on 127.0.0.1:7400","target":"flakelet_relay::relay::server"}
relay # [84967.809325] relay flakelet-relay[1323]: {"timestamp":"2026-09-06T06:15:28.938060Z","level":"INFO","message":"listening on [::]:7443","target":"flakelet_relay::relay::server"}
relay # [84967.808934] relay systemd[1]: Started flakelet-relay.
relay # [84968.381317] relay flakelet-relay[1323]: {"timestamp":"2026-09-06T06:15:29.510573Z","level":"INFO","message":"agent connected","host":"agent","version":"0.1.0","flakelets":"[Named { name: \"app\", generation: Some(7), revision: Some(\"prebuilt:app\") }, Named { name: \"other\", generation: Some(1), revision: Some(\"prebuilt:other\") }]","target":"flakelet_relay::relay::agent_conn"}
relay: (finished: waiting for success: curl -sf http://127.0.0.1:7400/metrics | grep -q 'agent_up{host="agent"} 1', in 1.04 seconds)
client: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem jobs
client: (finished: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem jobs, in 0.02 seconds)
client: must succeed: echo '{"groups": []}' | step crypto jwt sign --key /nix/store/r7sclamg09v434w8zjlfnrcrn1w79wh6-flakelet-relay-test-issuer/jwk.json --iss https://relay:8443 --aud flakelet-relay --sub 'repo:github:example/app:ref:refs/heads/main' --exp $(( $(date +%s) + 300 )) --jti $(head -c8 /dev/urandom | base32)
agent # [84968.381259] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:29.510520Z","level":"INFO","message":"connected","relay":"https://relay:7443","relay_name":"relay","relay_version":"0.1.0","host":"agent","target":"flakelet_relay::agent::conn"}
client: (finished: must succeed: echo '{"groups": []}' | step crypto jwt sign --key /nix/store/r7sclamg09v434w8zjlfnrcrn1w79wh6-flakelet-relay-test-issuer/jwk.json --iss https://relay:8443 --aud flakelet-relay --sub 'repo:github:example/app:ref:refs/heads/main' --exp $(( $(date +%s) + 300 )) --jti $(head -c8 /dev/urandom | base32), in 0.06 seconds)
client: must succeed: FLAKELET_RELAY_TOKEN_COMMAND='echo eyJhbGciOiJFZERTQSIsImtpZCI6ImsxIiwidHlwIjoiSldUIn0.eyJhdWQiOiJmbGFrZWxldC1yZWxheSIsImV4cCI6MTc4ODY3NTYzMCwiZ3JvdXBzIjpbXSwiaWF0IjoxNzg4Njc1MzMwLCJpc3MiOiJodHRwczovL3JlbGF5Ojg0NDMiLCJqdGkiOiJEN1ZKR0g3S0hSRlY2PT09IiwibmJmIjoxNzg4Njc1MzMwLCJzdWIiOiJyZXBvOmdpdGh1YjpleGFtcGxlL2FwcDpyZWY6cmVmcy9oZWFkcy9tYWluIn0.xyPeegCtYbiMow3k0t1GT0t8Z4U2uq2iYo4KAzM4dSlmb3-21ZmqG-qAc0iqztEXEejC9giHz_G3xz0MOmPCDw' push --relay https://relay:7443 jobs
client: (finished: must succeed: FLAKELET_RELAY_TOKEN_COMMAND='echo eyJhbGciOiJFZERTQSIsImtpZCI6ImsxIiwidHlwIjoiSldUIn0.eyJhdWQiOiJmbGFrZWxldC1yZWxheSIsImV4cCI6MTc4ODY3NTYzMCwiZ3JvdXBzIjpbXSwiaWF0IjoxNzg4Njc1MzMwLCJpc3MiOiJodHRwczovL3JlbGF5Ojg0NDMiLCJqdGkiOiJEN1ZKR0g3S0hSRlY2PT09IiwibmJmIjoxNzg4Njc1MzMwLCJzdWIiOiJyZXBvOmdpdGh1YjpleGFtcGxlL2FwcDpyZWY6cmVmcy9oZWFkcy9tYWluIn0.xyPeegCtYbiMow3k0t1GT0t8Z4U2uq2iYo4KAzM4dSlmb3-21ZmqG-qAc0iqztEXEejC9giHz_G3xz0MOmPCDw' push --relay https://relay:7443 jobs, in 0.02 seconds)
(finished: subtest: job history comes from the agents and survives a relay restart, in 4.41 seconds)
subtest: dashboard login via authorization code flow
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -o /dev/null -w '%{http_code} %{redirect_url}' https://relay:7443/ui/ | grep -q '303 https://relay:7443/ui/login'
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -o /dev/null -w '%{http_code} %{redirect_url}' https://relay:7443/ui/ | grep -q '303 https://relay:7443/ui/login', in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -L https://relay:7443/ui/login
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -L https://relay:7443/ui/login, in 0.09 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar https://relay:7443/ui/jobs
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar https://relay:7443/ui/jobs, in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -f https://relay:7443/v1/jobs | grep -q hist1
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -f https://relay:7443/v1/jobs | grep -q hist1, in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -N --max-time 10 https://relay:7443/ui/jobs/hist1/events || true
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -N --max-time 10 https://relay:7443/ui/jobs/hist1/events || true, in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -o /dev/null -w '%{http_code}' -X POST 'https://relay:7443/ui/deploy?arg=other' | grep -q 403
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -o /dev/null -w '%{http_code}' -X POST 'https://relay:7443/ui/deploy?arg=other' | grep -q 403, in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -D - -o /dev/null -H 'HX-Request: true' -X POST 'https://relay:7443/ui/deploy?arg=other'
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -D - -o /dev/null -H 'HX-Request: true' -X POST 'https://relay:7443/ui/deploy?arg=other', in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -N --max-time 30 https://relay:7443/ui/jobs/e8ad9998b92795e99537ef719d2e5d3d/events || true
relay # [84968.991790] relay 93sn3sv24fj26ksccpppzwg6kbf10s4w-device-mock[185]: 127.0.0.1 - - [06/Sep/2026 06:15:30] "GET /authorize?response_type=code&client_id=dashboard&redirect_uri=https%3A%2F%2Frelay%3A7443%2Fui%2Fcallback&scope=openid%20profile%20email%20groups&state=ryJccPXTE41y5X4MiTWpAyCLT7yE-Ygnwd4cr9j0uN4&code_challenge=I3lWc3H6RYYoUGETDTt3XQicCdOyRoAhaTh7L-wEd_A&code_challenge_method=S256 HTTP/1.1" 302 -
relay # [84969.044908] relay 93sn3sv24fj26ksccpppzwg6kbf10s4w-device-mock[185]: 127.0.0.1 - - [06/Sep/2026 06:15:30] "POST /token HTTP/1.1" 200 -
relay # [84969.045654] relay flakelet-relay[1323]: {"timestamp":"2026-09-06T06:15:30.174895Z","level":"INFO","message":"login","name":"someone","principals":"[\"oidc:mock:someone\", \"oidc:mock:groups:wheel\"]","target":"flakelet_relay::relay::login"}
relay # [84969.108393] relay flakelet-relay[1323]: {"timestamp":"2026-09-06T06:15:30.237657Z","level":"INFO","message":"job reattached","job":"188b06c4636b65849b3ba8daac22dc7c","targets":"[\"agent/other\"]","target":"flakelet_relay::relay::api"}
relay # [84969.149318] relay flakelet-relay[1323]: {"timestamp":"2026-09-06T06:15:30.278598Z","level":"INFO","message":"deploy accepted","job":"e8237b7e1d163f31bd30ffe5974f7bcd","caller":"oidc:mock:someone\noidc:mock:groups:wheel","targets":"[\"agent/other\"]","target":"flakelet_relay::relay::api"}
relay # [84969.166995] relay flakelet-relay[1323]: {"timestamp":"2026-09-06T06:15:30.296287Z","level":"INFO","message":"job reattached","job":"e8237b7e1d163f31bd30ffe5974f7bcd","targets":"[\"agent/other\"]","target":"flakelet_relay::relay::api"}
agent # [84969.149501] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:30.278756Z","level":"INFO","message":"start","id":"176b615e057aa56f0dcd0f7febf10c20","flakelet":"other","rule":"admins","relay":"relay","caller":"Some(\"oidc:mock:someone\\noidc:mock:groups:wheel\")","target":"flakelet_relay::agent::conn"}
agent # [84969.149781] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:30.279083Z","level":"INFO","message":"update starting","flakelet":"other","ids":"[\"176b615e057aa56f0dcd0f7febf10c20\"]","target":"flakelet_relay::agent::jobs"}
agent # [84969.215024] agent systemd[1]: Starting flakelet update other (via relay)...
agent # [84969.249326] agent systemd[1]: Started flakelet update other (via relay).
agent # [84969.253611] agent flakelet[3112]: other: using prebuilt artifact /nix/store/hmr990n0b4v6rpzrcpyyw738r9xi7z95-flakelet-other-v1
agent # [84969.254127] agent flakelet[3112]: other: up to date
agent # [84969.256485] agent systemd[1]: flakelet-relay-job-other.service: Deactivated successfully.
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -N --max-time 30 https://relay:7443/ui/jobs/e8ad9998b92795e99537ef719d2e5d3d/events || true, in 0.67 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar https://relay:7443/ui/jobs/e8ad9998b92795e99537ef719d2e5d3d
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar https://relay:7443/ui/jobs/e8ad9998b92795e99537ef719d2e5d3d, in 0.03 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -sf -o /dev/null https://relay:7443/ui/static/htmx.min.js
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -sf -o /dev/null https://relay:7443/ui/static/htmx.min.js, in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar 'https://relay:7443/ui/?q=status%3Ahealthy+oth'
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar 'https://relay:7443/ui/?q=status%3Ahealthy+oth', in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar https://relay:7443/ui/flakelets/other
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar https://relay:7443/ui/flakelets/other, in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar 'https://relay:7443/ui/hosts?q=status%3Adisconnected'
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar 'https://relay:7443/ui/hosts?q=status%3Adisconnected', in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -o /dev/null -w '%{http_code}' -H 'HX-Request: true' -X POST 'https://relay:7443/ui/retry?arg=e8ad9998b92795e99537ef719d2e5d3d' | grep -q 400
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -o /dev/null -w '%{http_code}' -H 'HX-Request: true' -X POST 'https://relay:7443/ui/retry?arg=e8ad9998b92795e99537ef719d2e5d3d' | grep -q 400, in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -N --max-time 15 'https://relay:7443/ui/events?path=jobs' > /tmp/ev.out 2>&1 &
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -N --max-time 15 'https://relay:7443/ui/events?path=jobs' > /tmp/ev.out 2>&1 &, in 0.01 seconds)
client: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy --id live1 agent/other
» job 38796a7ba508eadfe82a1cd5def000bc via relay 0.1.0 (agents: agent 0.1.0)
» wave 0
agent # [84969.814658] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:30.943873Z","level":"INFO","message":"update finished","flakelet":"other","status":"Unchanged","generation":"Some(1)","target":"flakelet_relay::agent::jobs"}
agent # [84969.961991] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:31.091186Z","level":"INFO","message":"start","id":"5e317fc57863c2a7c03ebe1bdacd1356","flakelet":"other","rule":"admins","relay":"relay","caller":"Some(\"x509:email:admin@example.org\")","target":"flakelet_relay::agent::conn"}
agent # [84969.962592] agent flakelet-agent[2462]: {"timestamp":"2026-09-06T06:15:31.091877Z","level":"INFO","message":"update starting","flakelet":"other","ids":"[\"5e317fc57863c2a7c03ebe1bdacd1356\"]","target":"flakelet_relay::agent::jobs"}
agent # [84970.032244] agent systemd[1]: Starting flakelet update other (via relay)...
agent/other | Starting flakelet update other (via relay)...
agent/other | Started flakelet update other (via relay).
agent/other | other: using prebuilt artifact /nix/store/hmr990n0b4v6rpzrcpyyw738r9xi7z95-flakelet-other-v1
agent/other | other: up to date
agent # [84970.071178] agent systemd[1]: Started flakelet update other (via relay).
agent # [84970.076867] agent flakelet[3130]: other: using prebuilt artifact /nix/store/hmr990n0b4v6rpzrcpyyw738r9xi7z95-flakelet-other-v1
agent # [84970.077375] agent flakelet[3130]: other: up to date
relay # [84969.961466] relay flakelet-relay[1323]: {"timestamp":"2026-09-06T06:15:31.090734Z","level":"INFO","message":"deploy accepted","job":"38796a7ba508eadfe82a1cd5def000bc","caller":"x509:email:admin@example.org","targets":"[\"agent/other\"]","target":"flakelet_relay::relay::api"}
agent # [84970.080524] agent systemd[1]: flakelet-relay-job-other.service: Deactivated successfully.
agent/other | flakelet-relay-job-other.service: Deactivated successfully.
» agent/other: unchanged (generation 1)
» ok
client: (finished: must succeed: push --relay https://relay:7443 --cert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin.pem --key /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/admin-key.pem deploy --id live1 agent/other, in 0.69 seconds)
client: waiting for success: grep -q live1 /tmp/ev.out
client: (finished: waiting for success: grep -q live1 /tmp/ev.out, in 0.01 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -X POST -o /dev/null https://relay:7443/ui/logout
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -X POST -o /dev/null https://relay:7443/ui/logout, in 0.02 seconds)
client: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -o /dev/null -w '%{http_code}' https://relay:7443/ui/ | grep -q 303
client: (finished: must succeed: curl -sS --cacert /nix/store/ydql3jgw8j7khsad67k605wlnywsd36n-flakelet-relay-test-certs/ca.pem -b /tmp/jar -c /tmp/jar -o /dev/null -w '%{http_code}' https://relay:7443/ui/ | grep -q 303, in 0.02 seconds)
(finished: subtest: dashboard login via authorization code flow, in 1.75 seconds)
(finished: run the VM test script, in 70.73 seconds)
test script finished in 70.78s
cleanup
kill NspawnMachine (pid 52)
kill NspawnMachine (pid 53)
Container agent terminated by signal KILL.
relay # [84970.636541] relay flakelet-relay[1323]: {"timestamp":"2026-09-06T06:15:31.765765Z","level":"INFO","message":"deploy finished","job":"38796a7ba508eadfe82a1cd5def000bc","ok":true,"target":"flakelet_relay::relay::api"}
kill NspawnMachine (pid 54)
Container client terminated by signal KILL.
Container relay terminated by signal KILL.
(finished: cleanup, in 0.44 seconds)
additionally exposed symbols:
    agent, client, relay,
    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
» job 7f630172135f1077f4a87a31e7dfb9d9 via relay 0.1.0 (agents: agent 0.1.0)
» wave 0
agent/app | Starting flakelet update app (via relay)...
agent/app | Started flakelet update app (via relay).
agent/app | app: using prebuilt artifact /nix/store/6ili1vxjlag9d7dy0bxrbxk6bpi5qh9p-flakelet-app-v2
agent/app | app: activating generation 2
agent/app | app: updated to generation 2
agent/app | flakelet-relay-job-app.service: Deactivated successfully.
» agent/app: updated (generation 2)
» ok

» job 233d11327806c6ba4302b8da0bf6b8a9 via relay 0.1.0 (agents: agent 0.1.0)
» wave 0
agent/app | Starting flakelet update app (via relay)...
agent/app | Started flakelet update app (via relay).
agent/app | app: using prebuilt artifact /nix/store/8282rnbvyk847q4l4zby3zwcq3jpzrvw-flakelet-app-broken
agent/app | app: activating generation 4
agent/app | app: deploy failed, rolled back: systemctl start app.service failed:
agent/app | failed units: app.service. See journalctl -u app.service
agent/app | flakelet-relay-job-app.service: Main process exited, code=exited, status=1/FAILURE
agent/app | flakelet-relay-job-app.service: Failed with result 'exit-code'.
» agent/app: rolled-back (generation 3)
agent/app │ Starting app v1...
agent/app │ Started app v1.
agent/app │ Stopping app v1...
agent/app │ app.service: Deactivated successfully.
agent/app │ Stopped app v1.
agent/app │ Starting app v2...
agent/app │ Started app v2.
agent/app │ Stopping app v2...
agent/app │ app.service: Deactivated successfully.
agent/app │ Stopped app v2.
agent/app │ Starting app v1...
agent/app │ Started app v1.
agent/app │ Stopping app v1...
agent/app │ app.service: Deactivated successfully.
agent/app │ Stopped app v1.
agent/app │ Starting app broken...
agent/app │ app.service: Unable to locate executable '/nonexistent': No such file or directory
agent/app │ app.service: Failed at step EXEC spawning /nonexistent: No such file or directory
agent/app │ app.service: Main process exited, code=exited, status=203/EXEC
agent/app │ app.service: Failed with result 'exit-code'.
agent/app │ Failed to start app broken.
agent/app │ Starting app v1...
agent/app │ Started app v1.
» skipped: agent/other
» failed

» job 1ec5f3b6d0fcfa69c747402c5d67d6e5 via relay 0.1.0 (agents: agent 0.1.0)
» wave 0
agent/app | Starting flakelet update app (via relay)...
agent/app | Started flakelet update app (via relay).
agent/app | app: using prebuilt artifact /nix/store/c67jj8kx3m50nyj874aqmdqf21w5iznd-flakelet-app-slow
agent/app | app: activating generation 5
agent/app | app: updated to generation 5
agent/app | flakelet-relay-job-app.service: Deactivated successfully.
» agent/app: updated (generation 5)
» ok

» job 9c34d306b5e457f2f406e05a8fbb7e1f via relay 0.1.0 (agents: agent 0.1.0)
» wave 0
agent/app | Starting flakelet update app (via relay)...
agent/app | Started flakelet update app (via relay).
agent/app | app: using prebuilt artifact /nix/store/ln47rsd5km8a04hd5zlkz4q1v352zqh3-flakelet-app-slow2
agent/app | app: activating generation 6
agent/app | app: updated to generation 6
agent/app | flakelet-relay-job-app.service: Deactivated successfully.
» agent/app: updated (generation 6)
» ok

» job c46a149e7623dfbfd5aecd8bb1d94a27 via relay 0.1.0 (agents: agent 0.1.0)
» wave 0
agent/app | Starting flakelet update app (via relay)...
agent/app | Started flakelet update app (via relay).
agent/app | app: using prebuilt artifact /nix/store/c67jj8kx3m50nyj874aqmdqf21w5iznd-flakelet-app-slow
agent/app | app: activating generation 7
flakelet-push: stream: error reading a body from connection, resuming job f7683a0ce29721a893dd359ba17cba13
flakelet-push: https://relay:7443: connect relay:7443: Connection refused (os error 111), retrying in 1s
flakelet-push: https://relay:7443: connect relay:7443: Connection refused (os error 111), retrying in 2s
flakelet-push: https://relay:7443: 404 Not Found: unknown_job: no connected agent knows this job, retrying in 4s
» job c46a149e7623dfbfd5aecd8bb1d94a27 via relay 0.1.0 (agents: agent 0.1.0)
» wave 0
agent/app | app: updated to generation 7
agent/app | flakelet-relay-job-app.service: Deactivated successfully.
» agent/app: updated (generation 7)
» ok

1788675325	hist1	x509:email:admin@example.org	agent/other:unchanged
1788675316	f7683a0ce29721a893dd359ba17cba13	x509:email:admin@example.org	agent/app:updated
1788675306	eb5c779a430282edcb4d478bee9f7140	x509:email:admin@example.org	agent/app:updated
1788675297	d050d46ecd9126c68d4b97f049ef602e	x509:email:admin@example.org	agent/app:updated
1788675296	8ace4d79cbf786d8c9ea4c19127dfe18	x509:email:admin@example.org	agent/other:unchanged
1788675284	62394e456da1426a48dd2e78304317f4	x509:email:admin@example.org	agent/app:updated
1788675279	3bfbb9f9530087af5ec2c6b46ae89995	oidc:mock:groups:wheel	agent/other:unchanged
1788675279	9bf48c7cda48d19e71679ef5253466d5	x509:email:admin@example.org	agent/app:rolled-back
1788675278	d35781d1578a43dcce2bdef9fe8387f9	oidc:mock:groups:wheel	agent/other:unchanged
1788675275	4398d84dff3af5c7a22b44068a165fe8	oidc:mock:groups:wheel	agent/other:unchanged
1788675272	2ce159da99576c3c57adebdf891c528e	oidc:mock:repo:github:example/app:ref:refs/heads/main	agent/app:updated
1788675269	d87e7fa6c6fd40d99a781b8f1ed6bb6b	x509:email:admin@example.org	agent/app:updated