build01: building 0gvwqpxpk6rh3cgv71y7bv5lnkqqkhs8-container-test-run-authelia.drv
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
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/nlf5kyx4kq26bwzskrvq0ilbx40qq78w-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
server: waiting for unit authelia-authelia.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 # No journal files were found.
server # No journal boot entry found for the specified boot (+0).
server # [520959.320570] server systemd-journald[190]: Journal started
server # [520959.320615] server systemd-journald[190]: Runtime Journal (/run/log/journal/129f82844ec34433b9b4de23cd08337f) is 8M, max 2.5G, 2.4G free.
server # [520959.324531] server systemd[1]: Finished Apply Kernel Variables.
server # [520959.335959] server systemd[1]: Finished Create Static Device Nodes in /dev gracefully.
server # [520959.347849] server systemd[1]: Starting Flush Journal to Persistent Storage...
server # [520959.348669] server systemd[1]: Starting Network Name Resolution...
server # [520959.349307] server systemd[1]: Starting Create Static Device Nodes in /dev...
server # [520959.356917] server systemd-journald[190]: Time spent on flushing to /var/log/journal/129f82844ec34433b9b4de23cd08337f is 1.512ms for 7 entries.
server # [520959.356917] server systemd-journald[190]: System Journal (/var/log/journal/129f82844ec34433b9b4de23cd08337f) is 8M, max 4G, 3.9G free.
server # [520959.371400] server systemd[1]: Finished Flush Journal to Persistent Storage.
server # [520959.371781] server systemd[1]: Finished Create Static Device Nodes in /dev.
server # [520959.372873] server systemd[1]: Reached target Preparation for Local File Systems.
server # [520959.372967] server systemd[1]: Reached target Local File Systems.
server # [520959.373605] server systemd[1]: Listening on Boot Loader Control Service Socket.
server # [520959.373651] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container
server # [520959.374541] server systemd[1]: Starting Save Transient machine-id to Disk...
server # [520959.375295] server systemd[1]: Starting Create System Files and Directories...
server # [520959.375324] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys
server # [520959.394190] server systemd-tmpfiles[239]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted
server # [520959.394391] server systemd-tmpfiles[239]: fchmod() of /var/log/journal failed: Operation not permitted
server # [520959.394531] server systemd-tmpfiles[239]: fchmod() of /var/log/journal/129f82844ec34433b9b4de23cd08337f failed: Operation not permitted
server # [520959.394735] server systemd-tmpfiles[239]: fchmod() of /run/log/journal failed: Operation not permitted
server # [520959.396108] server systemd[1]: Finished Create System Files and Directories.
server # [520959.397201] server systemd[1]: Starting Rebuild Journal Catalog...
server # [520959.397988] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...
server # [520959.405980] server systemd[1]: Finished Save Transient machine-id to Disk.
server # [520959.413766] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.
server # [520959.421781] server systemd[1]: Finished Rebuild Journal Catalog.
server # [520959.422774] server systemd[1]: Starting Update is Completed...
server # [520959.432727] server systemd[1]: Finished Update is Completed.
server # [520959.488133] server systemd[1]: Finished Firewall.
server # [520959.488289] server systemd[1]: Reached target Preparation for Network.
server # [520959.488518] server systemd[1]: Listening on Network Management Resolve Hook Socket.
server # [520959.489676] server systemd[1]: Starting Network Management...
server # [520960.096333] server systemd-networkd[304]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted
server # [520960.096421] server systemd-networkd[304]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted
server # [520960.105044] server systemd-networkd[304]: /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 # [520960.105202] server systemd-networkd[304]: /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 # [520960.105337] server systemd-networkd[304]: lo: Link UP
server # [520960.105342] server systemd-networkd[304]: lo: Gained carrier
server # [520960.105507] server systemd-networkd[304]: eth1: Configuring with /etc/systemd/network/40-eth1.network.
server # [520960.105946] server systemd-networkd[304]: eth1: Link UP
server # [520960.105954] server systemd[1]: Started Network Management.
server # [520960.106248] server systemd-networkd[304]: eth1: Gained carrier
server # [520960.107046] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...
server # [520960.148739] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.
server # [520960.330653] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
server # [520960.336352] server systemd-resolved[219]: Positive Trust Anchors:
server # [520960.336367] server systemd-resolved[219]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
server # [520960.336369] server systemd-resolved[219]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16
server # [520960.336404] server systemd-resolved[219]: 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 # [520960.337137] server systemd-resolved[219]: Using system hostname 'server'.
server # [520960.338777] server systemd[1]: Started Network Name Resolution.
server # [520960.338905] server systemd[1]: Reached target Network.
server # [520960.339010] server systemd[1]: Reached target Network is Online.
server # [520960.339095] server systemd[1]: Reached target System Initialization.
server # [520960.339182] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container
server # [520960.339236] server systemd[1]: Started Daily Cleanup of Temporary Directories.
server # [520960.339273] server systemd[1]: Reached target Timer Units.
server # [520960.339495] server systemd[1]: Listening on D-Bus System Message Bus Socket.
server # [520960.339742] server systemd[1]: Listening on Nix Daemon Socket.
server # [520960.339948] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.
server # [520960.339994] server systemd[1]: Reached target Socket Units.
server # [520960.340116] server systemd[1]: Reached target Basic System.
server # [520960.342708] server systemd[1]: Starting Authelia authentication and authorization server...
server # [520960.344128] server systemd[1]: Starting Caddy...
server # [520960.345436] server systemd[1]: Starting Import lastlog data into lastlog2 database...
server # [520960.347023] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...
server # [520960.380561] server systemd[1]: Starting D-Bus System Message Bus...
server # [520960.491245] server systemd[1]: Finished Import lastlog data into lastlog2 database.
server # [520960.577970] server systemd[1]: Started Name Service Cache Daemon (nsncd).
server # [520960.578063] server systemd[1]: Reached target Host and Network Name Lookups.
server # [520960.578165] server systemd[1]: Reached target User and Group Name Lookups.
server # [520960.578312] server nsncd[312]: Oct 22 10:06:05.550 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
server # [520960.580466] server systemd[1]: Starting User Login Management...
server # [520960.581916] server systemd[1]: Starting Permit User Sessions...
server # [520960.636353] server systemd[1]: Finished Permit User Sessions.
server # [520960.638152] server systemd[1]: Started Console Getty.
server # [520960.638231] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0
server # [520960.638270] server systemd[1]: Reached target Login Prompts.
server # [520960.691007] server dbus-broker-launch[313]: Looking up NSS user entry for 'systemd-timesync'...
server # [520960.692420] server dbus-broker-launch[313]: NSS returned no entry for 'systemd-timesync'
server # [520960.692420] server dbus-broker-launch[313]: Invalid user-name in /nix/store/f1jbcgzl4vchrm9dpspqmvzzlmbp0syy-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"
server # [520960.693433] server systemd[1]: Started D-Bus System Message Bus.
server # [520960.702473] server dbus-broker-launch[313]: Ready
server # [520960.922826] server systemd[1]: Started Caddy.
server # [520961.324401] server systemd-logind[332]: New seat seat0.
server # [520961.324908] server systemd[1]: Started User Login Management.
server # [520961.327215] server systemd[1]: Starting linger-users.service...
server # [520961.375124] server systemd[1]: linger-users.service: Failed to read pids.max for control group /system.slice/linger-users.service, ignoring: No data available
server # [520961.375223] server systemd[1]: linger-users.service: Failed to read pids.max for control group /system.slice/linger-users.service, ignoring: No data available
server # [520961.375282] server systemd[1]: linger-users.service: Deactivated successfully.
server # [520961.375592] server systemd[1]: Finished linger-users.service.
server # [520962.044117] server systemd-networkd[304]: eth1: Gained IPv6LL
server # [520962.203265] server authelia[375]: Configuration parsed and loaded successfully without errors.
server: (finished: waiting for unit authelia-authelia.service, in 5.16 seconds)
??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/nlf5kyx4kq26bwzskrvq0ilbx40qq78w-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:9091/api/health
??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/nlf5kyx4kq26bwzskrvq0ilbx40qq78w-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
server # [520963.021083] server systemd[1]: Started Authelia authentication and authorization server.
server # [520963.023074] server systemd[1]: Starting Punchcard time tracking (punchcard)...
server # [520963.073165] server authelia[409]: time="2026-10-22T10:06:08Z" level=info msg="Authelia v4.39.28-nixpkgs is starting"
server # [520963.073459] server authelia[409]: time="2026-10-22T10:06:08Z" level=info msg="Log severity set to info"
server # [520963.100551] server authelia[409]: time="2026-10-22T10:06:08Z" level=info msg="Storage schema is being checked for updates"
server # [520963.102130] server authelia[409]: time="2026-10-22T10:06:08Z" level=info msg="Storage schema migration from 0 to 29 is being attempted"
server # [520963.163564] server authelia[409]: time="2026-10-22T10:06:08Z" level=info msg="Storage schema migration from 0 to 29 is complete"
server # [520963.167990] server systemd-resolved[219]: Switching to fallback DNS server 1.1.1.1#one.one.one.one.
server # [520963.170454] server authelia[409]: time="2026-10-22T10:06:08Z" level=warning msg="Could not determine the clock offset due to an error" error="error occurred during dial: dial udp: lookup time.cloudflare.com: no such host"
server # [520963.218943] server systemd[1]: Started Punchcard time tracking (punchcard).
server # [520963.219435] server systemd[1]: Reached target Multi-User System.
server # [520963.219787] server systemd[1]: Startup finished in 4.266s.
server # [520963.228031] server punchcard-punchcard-start[413]: 2026/10/22 10:06:08 Warning: .env file not found, using environment variables: open .env: no such file or directory
server # [520963.237443] server punchcard-punchcard-start[413]: 2026/10/22 10:06:08 OIDC authentication enabled with issuer: https://auth.test.clan
server # [520963.237443] server punchcard-punchcard-start[413]: 2026/10/22 10:06:08 Redirect URL: https://punchcard.test.clan/callback
server # [520963.238041] server punchcard-punchcard-start[413]: 2026/10/22 10:06:08 Server starting on :8099
server # [520963.399118] server authelia[409]: time="2026-10-22T10:06:08Z" level=info msg="Startup complete"
server # [520963.399118] server authelia[409]: time="2026-10-22T10:06:08Z" level=info msg="Listening for non-TLS connections on '127.0.0.1:9091' path '/'" server=main service=server
server: (finished: waiting for success: curl -sf http://127.0.0.1:9091/api/health, in 1.04 seconds)
server: must succeed: test -f /run/authelia-authelia/users.json
server: (finished: must succeed: test -f /run/authelia-authelia/users.json, in 0.01 seconds)
server: must succeed: cat /run/authelia-authelia/users.json
server: (finished: must succeed: cat /run/authelia-authelia/users.json, in 0.01 seconds)
server: must succeed: test -f /run/authelia-authelia/oidc.json
server: (finished: must succeed: test -f /run/authelia-authelia/oidc.json, in 0.01 seconds)
server: must succeed: cat /run/authelia-authelia/oidc.json
server: (finished: must succeed: cat /run/authelia-authelia/oidc.json, in 0.01 seconds)
server: waiting for unit caddy.service
server: (finished: waiting for unit caddy.service, in 0.02 seconds)
server: waiting for success: curl -sf https://auth.test.clan/api/health
server: (finished: waiting for success: curl -sf https://auth.test.clan/api/health, in 0.10 seconds)
server: waiting for success: curl -sf https://auth.test.clan/.well-known/openid-configuration
server: (finished: waiting for success: curl -sf https://auth.test.clan/.well-known/openid-configuration, in 0.10 seconds)
??? Warning (UserWarning): wait_for_unit(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/nlf5kyx4kq26bwzskrvq0ilbx40qq78w-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
server: waiting for unit punchcard-punchcard.service
server: (finished: waiting for unit punchcard-punchcard.service, in 0.02 seconds)
server: waiting for success: curl -sf https://punchcard.test.clan/login
server: (finished: waiting for success: curl -sf https://punchcard.test.clan/login, in 0.07 seconds)
server: must succeed: cat /run/secrets/per-machine/server/authelia-user-bob/password
server: (finished: must succeed: cat /run/secrets/per-machine/server/authelia-user-bob/password, in 0.01 seconds)
server: must succeed: curl -s -o /dev/null -w '%{redirect_url}' -c /tmp/pc-cookies https://punchcard.test.clan/login/start
server: (finished: must succeed: curl -s -o /dev/null -w '%{redirect_url}' -c /tmp/pc-cookies https://punchcard.test.clan/login/start, in 0.21 seconds)
server: must succeed: curl -sf -X POST https://auth.test.clan/api/firstfactor -H 'Content-Type: application/json' -c /tmp/auth-cookies -d '{"username": "bob", "password": "slurp-rescuer-improvise-repulsive-antirust-amiable-unwarlike", "keepMeLoggedIn": false}'
server: (finished: must succeed: curl -sf -X POST https://auth.test.clan/api/firstfactor -H 'Content-Type: application/json' -c /tmp/auth-cookies -d '{"username": "bob", "password": "slurp-rescuer-improvise-repulsive-antirust-amiable-unwarlike", "keepMeLoggedIn": false}', in 1.15 seconds)
server: must succeed: curl -s -o /dev/null -w '%{redirect_url}' -b /tmp/auth-cookies -c /tmp/auth-cookies 'https://auth.test.clan/api/oidc/authorization?client_id=punchcard-punchcard&code_challenge=jg6D-IlVBdJFLIYvZuUesiMrrGtTJqOwXPWs9mm_QMA&code_challenge_method=S256&redirect_uri=https%3A%2F%2Fpunchcard.test.clan%2Fcallback&response_type=code&scope=openid+profile+email&state=MhRrJSEaeNeOGPRfh8DjwLvG7i9oFU_Rx2mlOY34LJ0%3D'
server: (finished: must succeed: curl -s -o /dev/null -w '%{redirect_url}' -b /tmp/auth-cookies -c /tmp/auth-cookies 'https://auth.test.clan/api/oidc/authorization?client_id=punchcard-punchcard&code_challenge=jg6D-IlVBdJFLIYvZuUesiMrrGtTJqOwXPWs9mm_QMA&code_challenge_method=S256&redirect_uri=https%3A%2F%2Fpunchcard.test.clan%2Fcallback&response_type=code&scope=openid+profile+email&state=MhRrJSEaeNeOGPRfh8DjwLvG7i9oFU_Rx2mlOY34LJ0%3D', in 0.11 seconds)
server: must succeed: curl -s -o /dev/null -w '%{http_code}' -c /tmp/pc-cookies -b /tmp/pc-cookies 'https://punchcard.test.clan/callback?code=authelia_ac_lyDWByoIn3GAAxjjN-vkf5TDXOs1Tl1brhMx46qPGtg.OiVEyAGcRIDY-WpikaOVYIrMxXIi100FEHErHkiII98&iss=https%3A%2F%2Fauth.test.clan&scope=openid+profile+email&state=MhRrJSEaeNeOGPRfh8DjwLvG7i9oFU_Rx2mlOY34LJ0%3D'
server: (finished: must succeed: curl -s -o /dev/null -w '%{http_code}' -c /tmp/pc-cookies -b /tmp/pc-cookies 'https://punchcard.test.clan/callback?code=authelia_ac_lyDWByoIn3GAAxjjN-vkf5TDXOs1Tl1brhMx46qPGtg.OiVEyAGcRIDY-WpikaOVYIrMxXIi100FEHErHkiII98&iss=https%3A%2F%2Fauth.test.clan&scope=openid+profile+email&state=MhRrJSEaeNeOGPRfh8DjwLvG7i9oFU_Rx2mlOY34LJ0%3D', in 0.32 seconds)
server: must succeed: curl -s -L -o /dev/null -w '%{http_code}' -b /tmp/pc-cookies -c /tmp/pc-cookies https://punchcard.test.clan/
server: (finished: must succeed: curl -s -L -o /dev/null -w '%{http_code}' -b /tmp/pc-cookies -c /tmp/pc-cookies https://punchcard.test.clan/, in 0.11 seconds)
(finished: run the VM test script, in 8.45 seconds)
test script finished in 8.46s
cleanup
kill NspawnMachine (pid 51)
server # [520966.309058] server authelia[409]: time="2026-10-22T10:06:11Z" level=error msg="Access Request failed with error: Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method). The required credentials were not found, used an unknown method, could not be parsed, were otherwise malformed, or were otherwise incorrect. The request was determined to be using 'token_endpoint_auth_method' method 'client_secret_basic', however the registered client with id 'punchcard-punchcard' is configured to only support 'token_endpoint_auth_method' method 'client_secret_post'. Either the Authorization Server client registration will need to have the 'token_endpoint_auth_method' updated to 'client_secret_basic' or the Relying Party will need to be configured to use 'client_secret_post'." method=POST path=/api/oidc/token remote_ip="::1"
server # [520966.523976] server punchcard-punchcard-start[413]: 2026/10/22 10:06:11 User  () logged in successfully
(finished: cleanup, in 0.11 seconds)
Container server terminated by signal KILL.