�[2mmachine # [    8.794829] dhcpcd[661]: eth0: adding default route via fe80::2�[0m
�[2mmachine # [    8.872133] dhcpcd[661]: eth0: soliciting a DHCP lease�[0m
�[2mmachine # [    9.008464] NET: Registered PF_PACKET protocol family�[0m
�[2mmachine # [    8.904563] dhcpcd[661]: eth0: offered 10.0.2.15 from 10.0.2.2�[0m
�[2mmachine # [    8.906467] dhcpcd[661]: eth0: leased 10.0.2.15 for 86400 seconds�[0m
�[2mmachine # [    8.907299] dhcpcd[661]: eth0: adding route to 10.0.2.0/24�[0m
�[2mmachine # [    8.907867] dhcpcd[661]: eth0: adding default route via 10.0.2.2�[0m
�[2mmachine # [    8.954140] postgresql-pre-start[806]: running bootstrap script ... ok�[0m
�[2mmachine # [    9.027386] systemd[1]: Stopped target Host and Network Name Lookups.�[0m
�[2mmachine # [    9.029442] systemd[1]: Stopping Host and Network Name Lookups...�[0m
�[2mmachine # [    9.032114] systemd[1]: Stopped target User and Group Name Lookups.�[0m
�[2mmachine # [    9.033422] systemd[1]: Stopping User and Group Name Lookups...�[0m
�[2mmachine # [    9.034562] systemd[1]: Stopping Name Service Cache Daemon (nsncd)...�[0m
�[2mmachine # [    9.035831] systemd[1]: nscd.service: Deactivated successfully.�[0m
�[2mmachine # [    9.038793] systemd[1]: Stopped Name Service Cache Daemon (nsncd).�[0m
�[2mmachine # [    9.055805] systemd[1]: Starting Name Service Cache Daemon (nsncd)...�[0m
�[2mmachine # [    9.081335] systemd[1]: Started DHCP Client.�[0m
�[2mmachine # [    9.088552] systemd[1]: Reached target Network is Online.�[0m
�[2mmachine # [    9.095430] systemd[1]: Started Lightweight LDAP server (lldap).�[0m
�[2mmachine # [    9.106866] nsncd[914]: Aug 13 01:56:13.250 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 3s }, path: "/var/run/nscd/socket"�[0m
�[2mmachine # [    9.108615] systemd[1]: Started Name Service Cache Daemon (nsncd).�[0m
�[2mmachine # [    9.111079] systemd[1]: Reached target Host and Network Name Lookups.�[0m
�[2mmachine # [    9.111805] systemd[1]: Reached target User and Group Name Lookups.�[0m
�[2mmachine # [    9.271330] lldap-start[935]: Loading configuration from /nix/store/xcrsvvzvwb36sxal43bkrdkhsq70gy9v-lldap_config.toml�[0m
(finished: waiting for unit lldap.service, in 11.23 seconds)
machine: �[1m�[32mwaiting for unit authelia-authelia.machine.service�[0m
(finished: waiting for unit authelia-authelia.machine.service, in 0.18 seconds)
machine: �[1m�[32mwaiting for TCP port 9091 on localhost�[0m
�[2mmachine # [   10.254264] lldap-start[935]: 2024-08-13T01:56:13.459919067+00:00  INFO     set_up_server [ 819ms | 100.00% ]�[0m
�[2mmachine # [   10.256518] lldap-start[935]: 2024-08-13T01:56:13.460435333+00:00  INFO     ┝━ ｉ [info]: Starting LLDAP version 0.5.0�[0m
�[2mmachine # [   10.258305] lldap-start[935]: 2024-08-13T01:56:13.517336979+00:00  INFO     ┝━ ｉ [info]: Upgrading DB schema from version 1�[0m
�[2mmachine # [   10.259979] lldap-start[935]: 2024-08-13T01:56:13.517343963+00:00  INFO     ┝━ ｉ [info]: Upgrading DB schema to version 2�[0m
�[2mmachine # [   10.261621] lldap-start[935]: 2024-08-13T01:56:13.524939341+00:00  INFO     ┝━ ｉ [info]: Upgrading DB schema to version 3�[0m
�[2mmachine # [   10.263420] lldap-start[935]: 2024-08-13T01:56:13.532643114+00:00  INFO     ┝━ ｉ [info]: Upgrading DB schema to version 4�[0m
�[2mmachine # [   10.266099] lldap-start[935]: 2024-08-13T01:56:13.536739165+00:00  INFO     ┝━ ｉ [info]: Upgrading DB schema to version 5�[0m
�[2mmachine # [   10.267187] lldap-start[935]: 2024-08-13T01:56:13.554544780+00:00  WARN     ┝━ 🚧 [warn]: Could not find lldap_admin group, trying to create it�[0m
�[2mmachine # [   10.268646] lldap-start[935]: 2024-08-13T01:56:13.562584908+00:00  WARN     ┝━ 🚧 [warn]: Could not find lldap_password_manager group, trying to create it�[0m
�[2mmachine # [   10.269972] lldap-start[935]: 2024-08-13T01:56:13.568796591+00:00  WARN     ┝━ 🚧 [warn]: Could not find lldap_strict_readonly group, trying to create it�[0m
�[2mmachine # [   10.271650] lldap-start[935]: 2024-08-13T01:56:13.578077939+00:00  WARN     ┝━ 🚧 [warn]: Could not find an admin user, trying to create the user "admin" with the config-provided password�[0m
�[2mmachine # [   10.273405] lldap-start[935]: 2024-08-13T01:56:14.377342929+00:00  INFO     ┝━ ｉ [info]: Starting the LDAP server on port 3890�[0m
�[2mmachine # [   10.274550] lldap-start[935]: 2024-08-13T01:56:14.397566170+00:00  INFO     ┕━ ｉ [info]: Starting the API/web server on port 17170�[0m
�[2mmachine # [   10.276292] lldap-start[935]: 2024-08-13T01:56:14.399797459+00:00  INFO     ｉ [info]: starting 1 workers�[0m
�[2mmachine # [   10.277775] lldap-start[935]: 2024-08-13T01:56:14.400790043+00:00  INFO     ｉ [info]: Actix runtime found; starting in Actix runtime�[0m
�[2mmachine # [   10.279253] lldap-start[935]: 2024-08-13T01:56:14.417059429+00:00  INFO     ｉ [info]: DB Cleanup Cron started�[0m
�[2mmachine # [   10.325957] postgresql-pre-start[806]: performing post-bootstrap initialization ... ok�[0m
�[2mmachine # [   10.437361] postgresql-pre-start[806]: syncing data to disk ... ok�[0m
�[2mmachine # [   10.438254] postgresql-pre-start[806]: initdb: warning: enabling "trust" authentication for local connections�[0m
�[2mmachine # [   10.439652] postgresql-pre-start[806]: initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.�[0m
�[2mmachine # [   10.441119] postgresql-pre-start[806]: Success. You can now start the database server using:�[0m
�[2mmachine # [   10.441894] postgresql-pre-start[806]:     /nix/store/hh1x7h54liwwclmwssmm66kdpa24im64-postgresql-and-plugins-15.7/bin/pg_ctl -D /var/lib/postgresql/15 -l logfile start�[0m
�[2mmachine # [   10.509833] postgres[960]: [960] LOG:  starting PostgreSQL 15.7 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 13.2.0, 64-bit�[0m
�[2mmachine # [   10.511951] postgres[960]: [960] LOG:  listening on IPv6 address "::1", port 5432�[0m
�[2mmachine # [   10.512764] postgres[960]: [960] LOG:  listening on IPv4 address "127.0.0.1", port 5432�[0m
�[2mmachine # [   10.514453] postgres[960]: [960] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"�[0m
�[2mmachine # [   10.520849] postgres[967]: [967] LOG:  database system was shut down at 2024-08-13 01:56:14 GMT�[0m
�[2mmachine # [   10.524866] postgres[960]: [960] LOG:  database system is ready to accept connections�[0m
�[2mmachine # [   10.625693] postgresql-post-start[978]: CREATE DATABASE�[0m
�[2mmachine # [   10.650968] postgresql-post-start[983]: CREATE ROLE�[0m
�[2mmachine # [   10.661813] postgresql-post-start[985]: ALTER ROLE�[0m
�[2mmachine # [   10.673333] postgresql-post-start[987]: ALTER DATABASE�[0m
�[2mmachine # [   10.677159] systemd[1]: Started PostgreSQL Server.�[0m
�[2mmachine # [   10.679299] systemd[1]: Reached target Multi-User System.�[0m
�[2mmachine # [   10.679909] systemd[1]: Startup finished in 3.122s (kernel) + 7.556s (userspace) = 10.679s.�[0m
�[2mmachine # [   10.986808] authelia[842]: {"level":"info","msg":"Storage schema is being checked for updates","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.004109] authelia[842]: {"level":"info","msg":"Storage schema migration from 0 to 7 is being attempted","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.034637] authelia[842]: {"level":"debug","msg":"Storage schema migrated from version 0 to 1","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.047152] authelia[842]: {"level":"debug","msg":"Storage schema migrated from version 1 to 2","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.053706] authelia[842]: {"level":"debug","msg":"Storage schema migrated from version 2 to 3","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.104340] authelia[842]: {"level":"debug","msg":"Storage schema migrated from version 3 to 4","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.106493] authelia[842]: {"level":"debug","msg":"Storage schema migrated from version 4 to 5","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.158770] authelia[842]: {"level":"debug","msg":"Storage schema migrated from version 5 to 6","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.183111] authelia[842]: {"level":"debug","msg":"Storage schema migrated from version 6 to 7","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.185185] authelia[842]: {"level":"info","msg":"Storage schema migration from 0 to 7 is complete","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.326221] authelia[842]: {"level":"debug","msg":"LDAP Supported OIDs. Control Types: none. Extensions: 1.3.6.1.4.1.4203.1.11.1","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.328797] lldap-start[935]: 2024-08-13T01:56:15.337882048+00:00  INFO     LDAP session [ 90.1ms | 1.61% / 100.00% ]�[0m
�[2mmachine # [   11.329772] lldap-start[935]: 2024-08-13T01:56:15.339727813+00:00  INFO     ┝━ LDAP request [ 88.5ms | 98.22% ]�[0m
�[2mmachine # [   11.330802] lldap-start[935]: 2024-08-13T01:56:15.429635609+00:00  INFO     ┕━ LDAP request [ 149µs | 0.17% ]�[0m
�[2mmachine # [   11.332401] authelia[842]: {"level":"debug","msg":"The NTP startup check was skipped due to there being no configured 2FA access control rules","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.335950] authelia[842]: {"level":"info","msg":"Initializing server (metrics) for non-TLS connections on '127.0.0.1:9959' path '/metrics'","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # [   11.365615] authelia[842]: {"level":"info","msg":"Initializing server for non-TLS connections on '127.0.0.1:9091' path '/'","time":"2024-08-13T01:56:15Z"}�[0m
�[2mmachine # Connection to localhost (127.0.0.1) 9091 port [tcp/xmltec-xmlmail] succeeded!�[0m
(finished: waiting for TCP port 9091 on localhost, in 2.11 seconds)
machine: �[1m�[32mmust succeed: curl -s http://machine/.well-known/openid-configuration�[0m
(finished: must succeed: curl -s http://machine/.well-known/openid-configuration, in 0.03 seconds)
machine: �[1m�[32mmust succeed: curl -f -s 'http://machine/api/oidc/authorization?client_id=other&redirect_uri=http://client1.machine/redirect&scope=openid%20profile%20email&response_type=code&state=99999999'�[0m
�[2mmachine # [   12.404335] authelia[842]: {"level":"error","method":"GET","msg":"Authorization Request failed with error: Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method). The requested OAuth 2.0 Client does not exist. not_found","path":"/api/oidc/authorization","remote_ip":"::1","stack":[{"File":"github.com/authelia/authelia/v4/internal/handlers/handler_oidc_authorization.go","Line":32,"Name":"OpenIDConnectAuthorization"},{"File":"github.com/authelia/authelia/v4/internal/middlewares/http_to_authelia_handler_adaptor.go","Line":113,"Name":"handleRouter.NewHTTPToAuth…
(finished: must succeed: curl -f -s 'http://machine/api/oidc/authorization?client_id=other&redirect_uri=http://client1.machine/redirect&scope=openid%20profile%20email&response_type=code&state=99999999', in 0.04 seconds)
machine: �[1m�[32mmust succeed: curl -f -s 'http://machine/api/oidc/authorization?client_id=client1&redirect_uri=http://client1.machine/redirect&scope=openid%20profile%20email&response_type=code&state=11111111'�[0m
�[2mmachine # [   12.445902] authelia[842]: {"level":"debug","method":"GET","msg":"Authorization Request with id '6bae2dc3-63e6-4665-8cd4-50b062f27ed6' on client with id 'client1' is being processed","path":"/api/oidc/authorization","remote_ip":"::1","time":"2024-08-13T01:56:16Z"}�[0m
(finished: must succeed: curl -f -s 'http://machine/api/oidc/authorization?client_id=client1&redirect_uri=http://client1.machine/redirect&scope=openid%20profile%20email&response_type=code&state=11111111', in 0.03 seconds)
machine: �[1m�[32mmust succeed: curl -f -s 'http://machine/api/oidc/authorization?client_id=client2&redirect_uri=http://client2.machine/redirect&scope=openid%20profile%20email&response_type=code&state=22222222'�[0m
�[2mmachine # [   12.472978] authelia[842]: {"level":"debug","method":"GET","msg":"Authorization Request with id '6c84ef99-99c5-4f11-ac72-ece89ca819c4' on client with id 'client2' is being processed","path":"/api/oidc/authorization","remote_ip":"::1","time":"2024-08-13T01:56:16Z"}�[0m
(finished: must succeed: curl -f -s 'http://machine/api/oidc/authorization?client_id=client2&redirect_uri=http://client2.machine/redirect&scope=openid%20profile%20email&response_type=code&state=22222222', in 0.03 seconds)
(finished: run the VM test script, in 13.77 seconds)
test script finished in 13.80s
�[1m�[32mcleanup�[0m
kill machine (pid 7)
qemu-kvm: terminating on signal 15 from pid 4 (/nix/store/7hnr99nxrd2aw6lghybqdmkckq60j6l9-python3-3.11.9/bin/python3.11)
(finished: cleanup, in 0.01 seconds)
kill vlan (pid 5)