build-x86-01: building 9im3smfw5n5cyx6xr225awbzsmx27qz3-container-test-run-pocket-id.drv
Machine state will be reset. To keep it, pass --keep-machine-state
start all VLans
(finished: start all VLans, in 0.00 seconds)

Test will time out and terminate in 3600.0 seconds
run the VM test script
additionally exposed symbols:
    server,
    vlan1,
    start_all, test_script, machines, machines_qemu, machines_nspawn, vlans, driver, log, os, create_machine, subtest, run_tests, join_all, retry, serial_stdout_off, serial_stdout_on, polling_condition, BaseMachine, QemuMachine, NspawnMachine, t, debug, dump_machine_ssh
start all VMs
server: systemd-nspawn running (pid 51)
server: Waiting for journal at /build/vm-state-server/var/log/journal...
(finished: start all VMs, in 0.00 seconds)
??? Warning (UserWarning): wait_for_unit(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/jjnpzllqpcg83qvmj4w6cmqb1zcqvrvl-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
server: waiting for unit pocket-id.service
nixos-nspawn(server): TAP vde-tap1 not found; container will be isolated from VDE
nixos-nspawn(server): A common reason for this is that /dev/net is not available in the Nix sandbox. Try adding /dev/net to extra-sandbox-paths.
Note: in a future version of systemd-nspawn the default set of permitted socket address families will be restricted to AF_INET, AF_INET6 and AF_UNIX. Use --restrict-address-families= to configure the set of permitted socket address families, or set RestrictAddressFamilies= in a .nspawn file.
░ Spawning container server on /build/vm-state-server.
server # [298477.324412] server systemd-journald[117]: Journal started
server # [298477.324441] server systemd-journald[117]: Runtime Journal (/run/log/journal/d7c1bce1b1ea49be8c71a71f3720cd88) is 8M, max 3.7G, 3.7G free.
server # [298477.327345] server systemd[1]: Finished Apply Kernel Variables.
server # [298477.333082] server systemd[1]: Finished Create Static Device Nodes in /dev gracefully.
server # [298477.339763] server systemd[1]: Starting Flush Journal to Persistent Storage...
server # [298477.340122] server systemd[1]: Starting Network Name Resolution...
server # [298477.340409] server systemd[1]: Starting Create Static Device Nodes in /dev...
server # [298477.344245] server systemd-journald[117]: Time spent on flushing to /var/log/journal/d7c1bce1b1ea49be8c71a71f3720cd88 is 1.029ms for 7 entries.
server # [298477.344245] server systemd-journald[117]: System Journal (/var/log/journal/d7c1bce1b1ea49be8c71a71f3720cd88) is 8M, max 4G, 3.9G free.
server # [298477.351156] server systemd[1]: Finished Flush Journal to Persistent Storage.
server # [298477.351308] server systemd[1]: Finished Create Static Device Nodes in /dev.
server # [298477.351865] server systemd[1]: Reached target Preparation for Local File Systems.
server # [298477.351905] server systemd[1]: Reached target Local File Systems.
server # [298477.352303] server systemd[1]: Listening on Boot Loader Control Service Socket.
server # [298477.352325] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container
server # [298477.352644] server systemd[1]: Starting Save Transient machine-id to Disk...
server # [298477.352973] server systemd[1]: Starting Create System Files and Directories...
server # [298477.352984] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys
server # [298477.361896] server systemd-tmpfiles[169]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted
server # [298477.362039] server systemd-tmpfiles[169]: fchmod() of /var/log/journal failed: Operation not permitted
server # [298477.362135] server systemd-tmpfiles[169]: fchmod() of /var/log/journal/d7c1bce1b1ea49be8c71a71f3720cd88 failed: Operation not permitted
server # [298477.362281] server systemd-tmpfiles[169]: fchmod() of /run/log/journal failed: Operation not permitted
server # [298477.362949] server systemd[1]: Finished Create System Files and Directories.
server # [298477.363359] server systemd[1]: Starting Rebuild Journal Catalog...
server # [298477.363665] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...
server # [298477.370063] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.
server # [298477.374946] server systemd[1]: Finished Rebuild Journal Catalog.
server # [298477.375503] server systemd[1]: Starting Update is Completed...
server # [298477.380547] server systemd[1]: Finished Update is Completed.
server # [298477.395170] server systemd[1]: Finished Save Transient machine-id to Disk.
server # [298477.405078] server systemd[1]: Finished Firewall.
server # [298477.405168] server systemd[1]: Reached target Preparation for Network.
server # [298477.405285] server systemd[1]: Listening on Network Management Resolve Hook Socket.
server # [298477.405683] server systemd[1]: Starting Network Management...
server # [298477.817048] server systemd-networkd[231]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted
server # [298477.817114] server systemd-networkd[231]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted
server # [298477.823501] server systemd-networkd[231]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.
server # [298477.823639] server systemd-networkd[231]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.
server # [298477.823703] server systemd-networkd[231]: lo: Link UP
server # [298477.823707] server systemd-networkd[231]: lo: Gained carrier
server # [298477.823844] server systemd-networkd[231]: eth1: Configuring with /etc/systemd/network/40-eth1.network.
server # [298477.824068] server systemd[1]: Started Network Management.
server # [298477.824084] server systemd-networkd[231]: eth1: Link UP
server # [298477.824230] server systemd-networkd[231]: eth1: Gained carrier
server # [298477.824627] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...
server # [298477.851369] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.
server # [298478.070474] server systemd-resolved[149]: Positive Trust Anchors:
server # [298478.070480] server systemd-resolved[149]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
server # [298478.070482] server systemd-resolved[149]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16
server # [298478.070498] server systemd-resolved[149]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 170.0.0.192.in-addr.arpa 171.0.0.192.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa ipv4only.arpa resolver.arpa corp home internal intranet lan local private test
server # [298478.080480] server systemd-resolved[149]: Using system hostname 'server'.
server # [298478.081218] server systemd[1]: Started Network Name Resolution.
server # [298478.081253] server systemd[1]: Reached target Network.
server # [298478.081279] server systemd[1]: Reached target Network is Online.
server # [298478.081298] server systemd[1]: Reached target System Initialization.
server # [298478.081323] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container
server # [298478.081337] server systemd[1]: Started Daily Cleanup of Temporary Directories.
server # [298478.081346] server systemd[1]: Reached target Timer Units.
server # [298478.081407] server systemd[1]: Listening on D-Bus System Message Bus Socket.
server # [298478.081462] server systemd[1]: Listening on Nix Daemon Socket.
server # [298478.081533] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.
server # [298478.081545] server systemd[1]: Reached target Socket Units.
server # [298478.081562] server systemd[1]: Reached target Basic System.
server # [298478.082096] server systemd[1]: Starting Caddy...
server # [298478.082418] server systemd[1]: Starting Import lastlog data into lastlog2 database...
server # [298478.082780] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...
server # [298478.083199] server systemd[1]: Started Pocket ID.
server # [298478.083563] server systemd[1]: Starting Reconcile Pocket ID OIDC clients and groups against the clan-declared spec...
server # [298478.098197] server systemd[1]: Starting D-Bus System Message Bus...
server # [298478.106608] server systemd[1]: Finished Import lastlog data into lastlog2 database.
server # [298478.107214] server pocket-id-clients-reconcile[248]: curl: (7) Failed to connect to 127.0.0.1:1411 after 0 ms: Could not connect to server
server # [298478.204872] server nsncd[238]: Oct 19 20:03:47.149 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
server # [298478.204855] server systemd[1]: Started Name Service Cache Daemon (nsncd).
server # [298478.204875] server systemd[1]: Reached target Host and Network Name Lookups.
server # [298478.204900] server systemd[1]: Reached target User and Group Name Lookups.
server # [298478.205407] server systemd[1]: Starting User Login Management...
server # [298478.205695] server systemd[1]: Starting Permit User Sessions...
server # [298478.231411] server systemd[1]: Finished Permit User Sessions.
server # [298478.231825] server systemd[1]: Started Console Getty.
server # [298478.231843] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0
server # [298478.231852] server systemd[1]: Reached target Login Prompts.
server # [298478.292821] server dbus-broker-launch[241]: Looking up NSS user entry for 'systemd-timesync'...
server # [298478.293216] server dbus-broker-launch[241]: NSS returned no entry for 'systemd-timesync'
server # [298478.293216] server dbus-broker-launch[241]: Invalid user-name in /nix/store/8rqxi5r4gyfjhh26qgdpm4f28lmfidb4-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"
server # [298478.293453] server systemd[1]: Started D-Bus System Message Bus.
server # [298478.297129] server dbus-broker-launch[241]: Ready
server # [298478.320699] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
server # [298478.469012] server systemd[1]: Started Caddy.
server # [298478.633015] server pocket-id-start[239]: Oct 19 20:03:47 INF Pocket ID is starting app=pocket-id version=2.18.0
server # [298478.633993] server pocket-id-start[239]: Oct 19 20:03:47 INF Connected to database app=pocket-id version=2.18.0 provider=sqlite
server # [298478.703267] server systemd-logind[261]: New seat seat0.
server # [298478.703393] server systemd[1]: Started User Login Management.
server # [298478.704110] server pocket-id-start[239]: Oct 19 20:03:47 INF Writing new application image app=pocket-id version=2.18.0 name=background.webp
server # [298478.704264] server systemd[1]: Starting linger-users.service...
server # [298478.704324] server pocket-id-start[239]: Oct 19 20:03:47 INF Writing new application image app=pocket-id version=2.18.0 name=favicon.ico
server # [298478.704347] server pocket-id-start[239]: Oct 19 20:03:47 INF Writing new application image app=pocket-id version=2.18.0 name=logoEmail.png
server # [298478.705807] server pocket-id-start[239]: Oct 19 20:03:47 WRN MAXMIND_LICENSE_KEY environment variable is empty: the GeoLite2 City database won't be updated app=pocket-id version=2.18.0 scope=geolite
server # [298478.723160] server pocket-id-start[239]: Oct 19 20:03:47 INF Creating metadata table app=pocket-id version=2.18.0 scope=actor-host table=francis_metadata
server # [298478.723298] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing migration app=pocket-id version=2.18.0 scope=actor-host component=migrations level=0
server # [298478.723314] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing SQLite database migration app=pocket-id version=2.18.0 scope=actor-host migration=01-schema.sql
server # [298478.723850] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing migration app=pocket-id version=2.18.0 scope=actor-host component=migrations level=1
server # [298478.723863] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing SQLite database migration app=pocket-id version=2.18.0 scope=actor-host migration=02-join-tokens.sql
server # [298478.723941] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing migration app=pocket-id version=2.18.0 scope=actor-host component=migrations level=2
server # [298478.723941] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing SQLite database migration app=pocket-id version=2.18.0 scope=actor-host migration=03-jobs.sql
server # [298478.725109] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing migration app=pocket-id version=2.18.0 scope=actor-host component=migrations level=3
server # [298478.725125] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing SQLite database migration app=pocket-id version=2.18.0 scope=actor-host migration=04-cluster.sql
server # [298478.725197] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing migration app=pocket-id version=2.18.0 scope=actor-host component=migrations level=4
server # [298478.725207] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing SQLite database migration app=pocket-id version=2.18.0 scope=actor-host migration=05-workflow-labels.sql
server # [298478.725681] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing migration app=pocket-id version=2.18.0 scope=actor-host component=migrations level=5
server # [298478.725681] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing SQLite database migration app=pocket-id version=2.18.0 scope=actor-host migration=06-terminal-jobs.sql
server # [298478.725886] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing migration app=pocket-id version=2.18.0 scope=actor-host component=migrations level=6
server # [298478.725886] server pocket-id-start[239]: Oct 19 20:03:47 INF Performing SQLite database migration app=pocket-id version=2.18.0 scope=actor-host migration=07-host-session-draining.sql
server # [298478.727091] server systemd[1]: linger-users.service: Deactivated successfully.
server # [298478.727193] server systemd[1]: Finished linger-users.service.
server # [298478.727595] server pocket-id-start[239]: Oct 19 20:03:47 INF Registered actor host app=pocket-id version=2.18.0 scope=actor-host hostId=01a155c3-5757-7e22-a39d-383ccf55ee74 address=0.0.0.0:1414
server # [298478.727633] server pocket-id-start[239]: Oct 19 20:03:47 INF Schedule expired data clean up app=pocket-id version=2.18.0 scope=actor-host interval=10m0s
server # [298478.727651] server pocket-id-start[239]: Oct 19 20:03:47 INF Server listening app=pocket-id version=2.18.0 addr=127.0.0.1:1411 tls=false
server # [298478.727722] server pocket-id-start[239]: Oct 19 20:03:47 INF Peer WebTransport server started app=pocket-id version=2.18.0 scope=actor-host bind=0.0.0.0:1414
server # [298478.729824] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job registered app=pocket-id version=2.18.0 cronJob=Analytics jobID=01a155c3-5759-7fff-bcb7-10d3ef515ee7
server # [298478.730890] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job registered app=pocket-id version=2.18.0 cronJob=ClearUnusedDefaultProfilePictures dueTime=2026-10-20T20:00:49.033Z
server # [298478.731916] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job registered app=pocket-id version=2.18.0 cronJob=ClearOrphanedTempFiles dueTime=2026-10-20T07:58:56.626Z
server # [298478.732473] server pocket-id-start[239]: Oct 19 20:03:47 INF AppConfig actor created app=pocket-id version=2.18.0 scope=actor actorType=AppConfig actorID=singleton
server # [298478.734299] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job registered app=pocket-id version=2.18.0 cronJob=ClearAuditLogs dueTime=2026-10-20T20:00:45.109Z
server # [298478.736274] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run started app=pocket-id version=2.18.0 cronJob=ClearAuditLogs
server # [298478.736788] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run started app=pocket-id version=2.18.0 cronJob=ClearWebauthnSessions
server # [298478.737166] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job registered app=pocket-id version=2.18.0 cronJob=ClearWebauthnSessions dueTime=2026-10-20T20:03:00.950Z
server # [298478.738682] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job registered app=pocket-id version=2.18.0 cronJob=ClearReauthenticationTokens dueTime=2026-10-20T20:01:50.287Z
server # [298478.741274] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job registered app=pocket-id version=2.18.0 cronJob=ClearOAuth2Sessions dueTime=2026-10-20T20:07:42.535Z
server # [298478.742754] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job registered app=pocket-id version=2.18.0 cronJob=ClearOAuth2JTIs dueTime=2026-10-20T20:00:49.439Z
server # [298478.745466] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run started app=pocket-id version=2.18.0 cronJob=ClearOAuth2Sessions
server # [298478.745914] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run started app=pocket-id version=2.18.0 cronJob=ClearInteractionSessions
server # [298478.746103] server pocket-id-start[239]: Oct 19 20:03:47 INF Cleaned interaction sessions app=pocket-id version=2.18.0 count=0
server # [298478.746103] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run completed app=pocket-id version=2.18.0 cronJob=ClearInteractionSessions duration=191.03µs
server # [298478.746650] server pocket-id-start[239]: Oct 19 20:03:47 INF Cleaned OAuth2 sessions app=pocket-id version=2.18.0 count=0
server # [298478.746650] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run completed app=pocket-id version=2.18.0 cronJob=ClearOAuth2Sessions duration=1.18374ms
server # [298478.747548] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run started app=pocket-id version=2.18.0 cronJob=ClearReauthenticationTokens
server # [298478.747681] server pocket-id-start[239]: Oct 19 20:03:47 INF Cleaned expired reauthentication tokens app=pocket-id version=2.18.0 count=0
server # [298478.747695] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run completed app=pocket-id version=2.18.0 cronJob=ClearReauthenticationTokens duration=133.231µs
server # [298478.748560] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run started app=pocket-id version=2.18.0 cronJob=Analytics
server # [298478.748880] server systemd-resolved[149]: Switching to fallback DNS server 1.1.1.1#one.one.one.one.
server # [298478.751907] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run started app=pocket-id version=2.18.0 cronJob=ClearOAuth2JTIs
server # [298478.752035] server pocket-id-start[239]: Oct 19 20:03:47 INF Cleaned OAuth2 client assertion JTIs app=pocket-id version=2.18.0 count=0
server # [298478.752045] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run completed app=pocket-id version=2.18.0 cronJob=ClearOAuth2JTIs duration=129.484µs
server # [298478.753019] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job registered app=pocket-id version=2.18.0 cronJob=ClearInteractionSessions dueTime=2026-10-20T20:05:31.697Z
server # [298478.755387] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job registered app=pocket-id version=2.18.0 cronJob=ExpiredApiKeyEmailJob dueTime=2026-10-20T00:01:24.582Z
server # [298478.770361] server pocket-id-start[239]: Oct 19 20:03:47 INF Cleaned expired WebAuthn sessions app=pocket-id version=2.18.0 count=0
server # [298478.770361] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run completed app=pocket-id version=2.18.0 cronJob=ClearWebauthnSessions duration=33.574347ms
server # [298478.770516] server pocket-id-start[239]: Oct 19 20:03:47 INF Deleted old audit logs app=pocket-id version=2.18.0 count=0
server # [298478.770516] server pocket-id-start[239]: Oct 19 20:03:47 INF Cron job run completed app=pocket-id version=2.18.0 cronJob=ClearAuditLogs duration=34.242045ms
server: (finished: waiting for unit pocket-id.service, in 2.64 seconds)
??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/jjnpzllqpcg83qvmj4w6cmqb1zcqvrvl-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
server: waiting for success: curl -sf http://127.0.0.1:1411/healthz
??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/jjnpzllqpcg83qvmj4w6cmqb1zcqvrvl-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
server: (finished: waiting for success: curl -sf http://127.0.0.1:1411/healthz, in 0.01 seconds)
server: waiting for success: curl -sf http://127.0.0.1:1411/.well-known/openid-configuration
server # [298479.121189] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=590dfe5c-da16-4de7-8220-3e1df6e0888c status=200 method=GET path=/api/user-groups query="search=admins" route=/api/user-groups ip=127.0.0.1 latency=1.662241ms referer="" user_agent=curl/8.22.0 body_size=90
server # [298479.122231] server pocket-id-clients-reconcile[240]: [group admins] create
server # [298479.130162] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=d8abcdd7-8b47-40c9-8978-d7139174bca4 status=201 method=POST path=/api/user-groups query="" route=/api/user-groups ip=127.0.0.1 latency=1.344583ms referer="" user_agent=curl/8.22.0 body_size=197
server # [298479.140504] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=3ca9dcdb-d40f-498f-acf5-21ea906ab8d3 error_code=not_found status=404 method=GET path=/api/oidc/clients/dashboard query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=217.67µs referer="" user_agent=curl/8.22.0 body_size=141
server # [298479.141404] server pocket-id-clients-reconcile[330]: [dashboard] create
server # [298479.146161] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=dbb57538-9804-4e31-9430-da679d29c844 status=201 method=POST path=/api/oidc/clients query="" route=/api/oidc/clients ip=127.0.0.1 latency=884.525µs referer="" user_agent=curl/8.22.0 body_size=849
server # [298479.154597] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=fdf4e850-58b0-4043-a6e2-fce466d56e38 status=200 method=PUT path=/api/oidc/clients/dashboard/allowed-user-groups query="" route=/api/oidc/clients/:id/allowed-user-groups ip=127.0.0.1 latency=2.647306ms referer="" user_agent=curl/8.22.0 body_size=626
server # [298479.160094] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=a6fdb9a0-c70b-4425-be7e-206275c20474 status=200 method=GET path=/api/oidc/clients/dashboard/secrets query="" route=/api/oidc/clients/:id/secrets ip=127.0.0.1 latency=410.142µs referer="" user_agent=curl/8.22.0 body_size=141
server # [298479.165473] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=ecae72a3-d4ff-4fa3-8a98-168d483098b4 status=204 method=DELETE path=/api/oidc/clients/dashboard/secrets/deb80852-6f93-48bb-9343-a0533f098d6c query="" route=/api/oidc/clients/:id/secrets/:secretId ip=127.0.0.1 latency=546.689µs referer="" user_agent=curl/8.22.0 body_size=-1
server # [298479.172081] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=9550fe94-901c-4297-924a-16b306121513 status=201 method=POST path=/api/oidc/clients/dashboard/secrets query="" route=/api/oidc/clients/:id/secrets ip=127.0.0.1 latency=510.171µs referer="" user_agent=curl/8.22.0 body_size=215
server # [298479.177963] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=4c4d6062-f567-40e3-b0f2-de24c2f80586 error_code=not_found status=404 method=GET path=/api/oidc/clients/fixture-app query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=218.201µs referer="" user_agent=curl/8.22.0 body_size=141
server # [298479.178442] server pocket-id-clients-reconcile[330]: [fixture-app] create
server # [298479.182137] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=25524656-b447-4f40-8a0b-398b7adbadd9 status=201 method=POST path=/api/oidc/clients query="" route=/api/oidc/clients ip=127.0.0.1 latency=533.395µs referer="" user_agent=curl/8.22.0 body_size=865
server # [298479.189075] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=a7a79b59-e75f-4585-9674-8dc9d7bb96ce status=200 method=GET path=/api/oidc/clients/fixture-app/secrets query="" route=/api/oidc/clients/:id/secrets ip=127.0.0.1 latency=377.871µs referer="" user_agent=curl/8.22.0 body_size=141
server # [298479.194063] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=a2875b32-70d2-43bb-9cef-bc16ec6833fc status=204 method=DELETE path=/api/oidc/clients/fixture-app/secrets/e569655f-ff8f-45d2-8e71-0cebd716fd48 query="" route=/api/oidc/clients/:id/secrets/:secretId ip=127.0.0.1 latency=466.549µs referer="" user_agent=curl/8.22.0 body_size=-1
server # [298479.200504] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=fad764b5-9552-446e-ace6-08f99e7d4f26 status=201 method=POST path=/api/oidc/clients/fixture-app/secrets query="" route=/api/oidc/clients/:id/secrets ip=127.0.0.1 latency=482.408µs referer="" user_agent=curl/8.22.0 body_size=215
server # [298479.206469] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=dbbc7ca0-6360-458d-9d44-c0bc72eeaf47 error_code=not_found status=404 method=GET path=/api/oidc/clients/webapp-public query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=161.334µs referer="" user_agent=curl/8.22.0 body_size=141
server # [298479.207359] server pocket-id-clients-reconcile[330]: [webapp-public] create
server # [298479.211370] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=b6b579d7-d592-47a0-b097-9c2346a00604 status=201 method=POST path=/api/oidc/clients query="" route=/api/oidc/clients ip=127.0.0.1 latency=482.108µs referer="" user_agent=curl/8.22.0 body_size=511
server # [298479.214986] server systemd[1]: Finished Reconcile Pocket ID OIDC clients and groups against the clan-declared spec.
server # [298479.222508] server systemd[1]: Reached target Multi-User System.
server # [298479.222593] server systemd[1]: Startup finished in 2.120s.
server: (finished: waiting for success: curl -sf http://127.0.0.1:1411/.well-known/openid-configuration, in 0.01 seconds)
??? Warning (UserWarning): wait_for_unit(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/jjnpzllqpcg83qvmj4w6cmqb1zcqvrvl-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
server: waiting for unit pocket-id-clients.service
server: (finished: waiting for unit pocket-id-clients.service, in 0.01 seconds)
server: must succeed: cat /run/secrets/per-machine/server/pocket-id/api-key
server: (finished: must succeed: cat /run/secrets/per-machine/server/pocket-id/api-key, in 0.00 seconds)
server: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/oidc/clients
server: (finished: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/oidc/clients, in 0.01 seconds)
server: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/user-groups
server: (finished: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/user-groups, in 0.01 seconds)
server: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/oidc/clients/dashboard
server: (finished: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/oidc/clients/dashboard, in 0.01 seconds)
server: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/oidc/clients/fixture-app
server: (finished: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/oidc/clients/fixture-app, in 0.01 seconds)
server: must succeed: systemctl restart pocket-id-clients.service
server: (finished: must succeed: systemctl restart pocket-id-clients.service, in 0.13 seconds)
server: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/oidc/clients/dashboard/secrets
server: (finished: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/oidc/clients/dashboard/secrets, in 0.01 seconds)
server: must succeed: systemctl restart pocket-id-clients.service
server # [298479.484120] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=c4962ae1-f81e-4443-afd3-f957c971143e status=200 method=GET path=/.well-known/openid-configuration query="" route=/.well-known/openid-configuration ip=127.0.0.1 latency=215.055µs referer="" user_agent=curl/8.22.0 body_size=1807
server # [298479.503520] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=b6a3ca3c-9ac4-43cd-a976-07c740b9bb9b status=200 method=GET path=/api/oidc/clients query="" route=/api/oidc/clients ip=127.0.0.1 latency=1.951535ms referer="" user_agent=curl/8.22.0 body_size=2083
server # [298479.511347] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=da04360b-6677-4cc8-89fb-dbbd71f84ce3 status=200 method=GET path=/api/user-groups query="" route=/api/user-groups ip=127.0.0.1 latency=647.96µs referer="" user_agent=curl/8.22.0 body_size=256
server # [298479.518806] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=fb152bb7-9a5e-4be3-9c15-27e047c61b00 status=200 method=GET path=/api/oidc/clients/dashboard query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=621.21µs referer="" user_agent=curl/8.22.0 body_size=815
server # [298479.526109] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=644d624c-4dfd-4dac-82f6-238e367adfc0 status=200 method=GET path=/api/oidc/clients/fixture-app query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=391.728µs referer="" user_agent=curl/8.22.0 body_size=665
server # [298479.531411] server systemd[1]: pocket-id-clients.service: Deactivated successfully.
server # [298479.531516] server systemd[1]: Stopped Reconcile Pocket ID OIDC clients and groups against the clan-declared spec.
server # [298479.531547] server systemd[1]: Stopping Reconcile Pocket ID OIDC clients and groups against the clan-declared spec...
server # [298479.532165] server systemd[1]: Starting Reconcile Pocket ID OIDC clients and groups against the clan-declared spec...
server # [298479.570063] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=003ebaed-2918-4910-8968-02779046c35b status=200 method=GET path=/api/user-groups query="search=admins" route=/api/user-groups ip=127.0.0.1 latency=447.272µs referer="" user_agent=curl/8.22.0 body_size=256
server # [298479.581330] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=d560b675-8e2b-4643-a27f-f7ccb1d2f364 status=200 method=GET path=/api/oidc/clients/dashboard query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=477.078µs referer="" user_agent=curl/8.22.0 body_size=815
server # [298479.581841] server pocket-id-clients-reconcile[379]: [dashboard] update
server # [298479.586303] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=d703ba89-3338-49f1-9af3-37f600ab2294 status=200 method=PUT path=/api/oidc/clients/dashboard query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=864.518µs referer="" user_agent=curl/8.22.0 body_size=825
server # [298479.594635] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=0c98e0b1-379f-4f10-8385-0a63f91c5247 status=200 method=PUT path=/api/oidc/clients/dashboard/allowed-user-groups query="" route=/api/oidc/clients/:id/allowed-user-groups ip=127.0.0.1 latency=1.731562ms referer="" user_agent=curl/8.22.0 body_size=626
server # [298479.599536] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=55780ce8-830b-453a-9464-8d82f67b1603 status=200 method=GET path=/api/oidc/clients/dashboard/secrets query="" route=/api/oidc/clients/:id/secrets ip=127.0.0.1 latency=290.647µs referer="" user_agent=curl/8.22.0 body_size=141
server # [298479.604744] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=7169abea-8387-4fe7-831d-e7891aa600f6 status=204 method=DELETE path=/api/oidc/clients/dashboard/secrets/7ac00bfc-2341-4b80-a8c5-0bef04b174c6 query="" route=/api/oidc/clients/:id/secrets/:secretId ip=127.0.0.1 latency=533.866µs referer="" user_agent=curl/8.22.0 body_size=-1
server # [298479.611223] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=1f21acfa-c5f8-4be8-8604-48152002880f status=201 method=POST path=/api/oidc/clients/dashboard/secrets query="" route=/api/oidc/clients/:id/secrets ip=127.0.0.1 latency=508.448µs referer="" user_agent=curl/8.22.0 body_size=215
server # [298479.617962] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=cd4bc6de-2602-45ea-b89e-4a7fda43a63c status=200 method=GET path=/api/oidc/clients/fixture-app query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=356.131µs referer="" user_agent=curl/8.22.0 body_size=665
server # [298479.618847] server pocket-id-clients-reconcile[379]: [fixture-app] update
server # [298479.622885] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=38fc7445-a7f9-4c3e-8020-1279e52f6952 status=200 method=PUT path=/api/oidc/clients/fixture-app query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=524.297µs referer="" user_agent=curl/8.22.0 body_size=665
server # [298479.629692] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=c638f53a-57e3-4f38-939d-f90f248b1f4a status=200 method=GET path=/api/oidc/clients/fixture-app/secrets query="" route=/api/oidc/clients/:id/secrets ip=127.0.0.1 latency=415.592µs referer="" user_agent=curl/8.22.0 body_size=141
server # [298479.635226] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=5692f9d0-3ec5-47da-a340-ad6f5a7b3485 status=204 method=DELETE path=/api/oidc/clients/fixture-app/secrets/67591aa1-ae98-4ba6-a28c-c6173983afc9 query="" route=/api/oidc/clients/:id/secrets/:secretId ip=127.0.0.1 latency=517.244µs referer="" user_agent=curl/8.22.0 body_size=-1
server # [298479.642134] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=fff37f1f-2596-4fd7-8591-52e6ef556312 status=201 method=POST path=/api/oidc/clients/fixture-app/secrets query="" route=/api/oidc/clients/:id/secrets ip=127.0.0.1 latency=504.821µs referer="" user_agent=curl/8.22.0 body_size=215
server # [298479.648361] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=22d10a32-e4d2-469f-877d-51a9d309dd53 status=200 method=GET path=/api/oidc/clients/webapp-public query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=294.154µs referer="" user_agent=curl/8.22.0 body_size=511
server # [298479.648832] server pocket-id-clients-reconcile[379]: [webapp-public] update
server # [298479.652881] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=877780f3-1796-4a90-86ce-e84e384dfc6d status=200 method=PUT path=/api/oidc/clients/webapp-public query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=771.112µs referer="" user_agent=curl/8.22.0 body_size=511
server # [298479.656625] server systemd[1]: Finished Reconcile Pocket ID OIDC clients and groups against the clan-declared spec.
server # [298479.663299] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=ac280d07-b711-40c8-9ce5-cc6f80ff397b status=200 method=GET path=/api/oidc/clients/dashboard/secrets query="" route=/api/oidc/clients/:id/secrets ip=127.0.0.1 latency=359.006µs referer="" user_agent=curl/8.22.0 body_size=141
server # [298479.668330] server systemd[1]: pocket-id-clients.service: Deactivated successfully.
server # [298479.668403] server systemd[1]: Stopped Reconcile Pocket ID OIDC clients and groups against the clan-declared spec.
server # [298479.668426] server systemd[1]: Stopping Reconcile Pocket ID OIDC clients and groups against the clan-declared spec...
server # [298479.668921] server systemd[1]: Starting Reconcile Pocket ID OIDC clients and groups against the clan-declared spec...
server # [298479.678064] server systemd-networkd[231]: eth1: Gained IPv6LL
server # [298479.702988] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=52af977c-ac53-474b-b1cb-cdf08deddca2 status=200 method=GET path=/api/user-groups query="search=admins" route=/api/user-groups ip=127.0.0.1 latency=417.616µs referer="" user_agent=curl/8.22.0 body_size=256
server # [298479.713561] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=4c00f663-d8d2-4a7e-ba1c-674c464600ee status=200 method=GET path=/api/oidc/clients/dashboard query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=337.926µs referer="" user_agent=curl/8.22.0 body_size=815
server # [298479.714435] server pocket-id-clients-reconcile[420]: [dashboard] update
server # [298479.718510] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=a1b7e739-4b1e-476e-927a-7e6fd1303241 status=200 method=PUT path=/api/oidc/clients/dashboard query="" route=/api/oidc/clients/:id ip=127.0.0.1 latency=561.157µs referer="" user_agent=curl/8.22.0 body_size=825
server # [298479.726544] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=0ca7c353-324e-4fa0-bcd6-5ed919974b19 status=200 method=PUT path=/api/oidc/clients/dashboard/allowed-user-groups query="" route=/api/oidc/clients/:id/allowed-user-groups ip=127.0.0.1 latency=1.616054ms referer="" user_agent=curl/8.22.0 body_size=626
server # [298479.732327] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=f2bf3ba4-53ed-4bba-8b42-094a397c47a9 status=200 method=GET path=/api/oidc/clients/dashboard/secrets query="" route=/api/oidc/clients/:id/secrets ip=127.0.0.1 latency=374.656µs referer="" user_agent=curl/8.22.0 body_size=141
server # [298479.737742] server pocket-id-start[239]: Oct 19 20:03:48 INF HTTP request completed app=pocket-id version=2.18.0 request_id=62178b96-2c79-44aa-bb1e-bc765f0ad370 status=204 method=DELETE path=/api/oidc/clients/dashboard/secrets/025b12d4-e2fe-43be-a31e-9a27a28649d8 query="" route=/api/oidc/clients/:id/secrets/:secretId ip=127.0.0.1 latency=485.535µs referer="" user_agent=curl/8.22.0 body_size=-1
server: (finished: must succeed: systemctl restart pocket-id-clients.service, in 0.13 seconds)
server: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/oidc/clients/dashboard/secrets
server: (finished: must succeed: curl -sf -H 'X-API-Key: ff878c4cbb84ed6e24c1f74e0dd4aada2016afc19bc0f8771a0e49848619b070' http://127.0.0.1:1411/api/oidc/clients/dashboard/secrets, in 0.01 seconds)
server: must succeed: curl -sf -u dashboard:$(cat /run/secrets/per-machine/server/pocket-id-client-dashboard/secret) -d grant_type=client_credentials http://127.0.0.1:1411/api/oidc/token
server: (finished: must succeed: curl -sf -u dashboard:$(cat /run/secrets/per-machine/server/pocket-id-client-dashboard/secret) -d grant_type=client_credentials http://127.0.0.1:1411/api/oidc/token, in 0.01 seconds)
server: must fail: curl -sf -u dashboard:wrong-secret-0000 -d grant_type=client_credentials http://127.0.0.1:1411/api/oidc/token
server: (finished: must fail: curl -sf -u dashboard:wrong-secret-0000 -d grant_type=client_credentials http://127.0.0.1:1411/api/oidc/token, in 0.01 seconds)
server: waiting for unit caddy.service
server: (finished: waiting for unit caddy.service, in 0.01 seconds)
server: waiting for success: curl -sf https://id.test.clan/healthz
server: (finished: waiting for success: curl -sf https://id.test.clan/healthz, in 0.02 seconds)
(finished: run the VM test script, in 3.01 seconds)
test script finished in 3.02s
cleanup
kill NspawnMachine (pid 51)
(finished: cleanup, in 0.06 seconds)
Container server terminated by signal KILL.