these 18 derivations will be built:
  /nix/store/xwiycl07kcxrbmqa0x7rbrgmm41w6aaa-system-path.drv
  /nix/store/x2igkfzmp519hyfhi0vnj88r9ddjjbng-dbus-1.drv
  /nix/store/c2bi2hr443nxn5lg51lxd0vsnyqxiq07-X-Restart-Triggers-dbus-broker.drv
  /nix/store/4vnak5bh6ikv5x5ms218jah86rhq68b8-unit-dbus-broker.service.drv
  /nix/store/7xvzs3h5ds6s790cbhpyql2jyqfj4n44-unit-horae.service.drv
  /nix/store/l4xvv9jgj6bdvx9cj36hhmmp02q9ffy0-unit-dbus-broker.service.drv
  /nix/store/lc43a31h0bw08pvqxx6qf2707vnbn8mv-user-units.drv
  /nix/store/p1d0aks6wwlxqz5l10r4s37qcc21p927-system-units.drv
  /nix/store/8pkbn9limcbx3kn63h50axnkj96f7ssg-etc.drv
  /nix/store/zf5x75ggacna05zdjmpawf75y8ixyx92-activate.drv
  /nix/store/j7rcxmj55q8mvfa3z7gyd56l8kld61dv-nixos-system-server-test.drv
  /nix/store/gxf1pi662aa77rph3clq5nz264hklnai-closure-info.drv
  /nix/store/plw7i336hgjihnbpylk40gxi6wad92x6-closure-info.drv
  /nix/store/mbpd3ir2sf58mhwwvwcpcqqsyasnpk5c-run-nixos-vm.drv
  /nix/store/spi8fcy63j1bm5xsmgg821lvwky14f06-nixos-vm.drv
  /nix/store/9ips75z7cdxnnvc6kf51dgk8y5ymdd8r-driverConfiguration.json.drv
  /nix/store/n1aaid4js7k86k0warsnyjpflpp4qmy2-nixos-test-driver-horae-e2e-oidc.drv
  /nix/store/gjywx06fh5svsllp19qbybxl0v43rphj-vm-test-run-horae-e2e-oidc.drv
building '/nix/store/xwiycl07kcxrbmqa0x7rbrgmm41w6aaa-system-path.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=21&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/7xvzs3h5ds6s790cbhpyql2jyqfj4n44-unit-horae.service.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=23&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/7xvzs3h5ds6s790cbhpyql2jyqfj4n44-unit-horae.service.drv' on farm.numtide.com:50051
unit-horae.service> elastic-arm-f49ce1c9: building 7xvzs3h5ds6s790cbhpyql2jyqfj4n44-unit-horae.service.drv
building '/nix/store/xwiycl07kcxrbmqa0x7rbrgmm41w6aaa-system-path.drv' on farm.numtide.com:50051
system-path> elastic-arm-2c90f239: building xwiycl07kcxrbmqa0x7rbrgmm41w6aaa-system-path.drv
system-path> structuredAttrs is enabled
system-path> created 7472 symlinks in user environment
system-path> install-info: warning: no info dir entry in `/nix/store/0xan9m14qz63l4y6vcyfrrbjv937fng3-system-path/share/info/notes.info'
building '/nix/store/x2igkfzmp519hyfhi0vnj88r9ddjjbng-dbus-1.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=21&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/x2igkfzmp519hyfhi0vnj88r9ddjjbng-dbus-1.drv' on farm.numtide.com:50051
dbus-1> elastic-arm-2c90f239: building x2igkfzmp519hyfhi0vnj88r9ddjjbng-dbus-1.drv
building '/nix/store/c2bi2hr443nxn5lg51lxd0vsnyqxiq07-X-Restart-Triggers-dbus-broker.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=22&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/c2bi2hr443nxn5lg51lxd0vsnyqxiq07-X-Restart-Triggers-dbus-broker.drv' on farm.numtide.com:50051
X-Restart-Triggers-dbus-broker> elastic-arm-2c90f239: building c2bi2hr443nxn5lg51lxd0vsnyqxiq07-X-Restart-Triggers-dbus-broker.drv
building '/nix/store/4vnak5bh6ikv5x5ms218jah86rhq68b8-unit-dbus-broker.service.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=22&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/l4xvv9jgj6bdvx9cj36hhmmp02q9ffy0-unit-dbus-broker.service.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=20&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/4vnak5bh6ikv5x5ms218jah86rhq68b8-unit-dbus-broker.service.drv' on farm.numtide.com:50051
unit-dbus-broker.service> elastic-arm-2c90f239: building 4vnak5bh6ikv5x5ms218jah86rhq68b8-unit-dbus-broker.service.drv
building '/nix/store/l4xvv9jgj6bdvx9cj36hhmmp02q9ffy0-unit-dbus-broker.service.drv' on farm.numtide.com:50051
unit-dbus-broker.service> elastic-arm-2c90f239: building l4xvv9jgj6bdvx9cj36hhmmp02q9ffy0-unit-dbus-broker.service.drv
building '/nix/store/p1d0aks6wwlxqz5l10r4s37qcc21p927-system-units.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=22&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/lc43a31h0bw08pvqxx6qf2707vnbn8mv-user-units.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=21&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/p1d0aks6wwlxqz5l10r4s37qcc21p927-system-units.drv' on farm.numtide.com:50051
system-units> elastic-arm-2c90f239: building p1d0aks6wwlxqz5l10r4s37qcc21p927-system-units.drv
building '/nix/store/lc43a31h0bw08pvqxx6qf2707vnbn8mv-user-units.drv' on farm.numtide.com:50051
user-units> elastic-arm-2c90f239: building lc43a31h0bw08pvqxx6qf2707vnbn8mv-user-units.drv
building '/nix/store/8pkbn9limcbx3kn63h50axnkj96f7ssg-etc.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=20&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/8pkbn9limcbx3kn63h50axnkj96f7ssg-etc.drv' on farm.numtide.com:50051
etc> elastic-arm-2c90f239: building 8pkbn9limcbx3kn63h50axnkj96f7ssg-etc.drv
building '/nix/store/zf5x75ggacna05zdjmpawf75y8ixyx92-activate.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=20&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/zf5x75ggacna05zdjmpawf75y8ixyx92-activate.drv' on farm.numtide.com:50051
activate> elastic-arm-2c90f239: building zf5x75ggacna05zdjmpawf75y8ixyx92-activate.drv
building '/nix/store/j7rcxmj55q8mvfa3z7gyd56l8kld61dv-nixos-system-server-test.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=20&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/j7rcxmj55q8mvfa3z7gyd56l8kld61dv-nixos-system-server-test.drv' on farm.numtide.com:50051
nixos-system-server-test> elastic-arm-ebe5bb33: building j7rcxmj55q8mvfa3z7gyd56l8kld61dv-nixos-system-server-test.drv
nixos-system-server-test> structuredAttrs is enabled
building '/nix/store/gxf1pi662aa77rph3clq5nz264hklnai-closure-info.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=20&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/gxf1pi662aa77rph3clq5nz264hklnai-closure-info.drv' on farm.numtide.com:50051
closure-info> elastic-arm-2c90f239: building gxf1pi662aa77rph3clq5nz264hklnai-closure-info.drv
closure-info> structuredAttrs is enabled
building '/nix/store/plw7i336hgjihnbpylk40gxi6wad92x6-closure-info.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=20&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/plw7i336hgjihnbpylk40gxi6wad92x6-closure-info.drv' on farm.numtide.com:50051
closure-info> elastic-arm-2c90f239: building plw7i336hgjihnbpylk40gxi6wad92x6-closure-info.drv
closure-info> structuredAttrs is enabled
building '/nix/store/mbpd3ir2sf58mhwwvwcpcqqsyasnpk5c-run-nixos-vm.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=20&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/mbpd3ir2sf58mhwwvwcpcqqsyasnpk5c-run-nixos-vm.drv' on farm.numtide.com:50051
run-nixos-vm> elastic-arm-2c90f239: building mbpd3ir2sf58mhwwvwcpcqqsyasnpk5c-run-nixos-vm.drv
building '/nix/store/spi8fcy63j1bm5xsmgg821lvwky14f06-nixos-vm.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=20&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/spi8fcy63j1bm5xsmgg821lvwky14f06-nixos-vm.drv' on farm.numtide.com:50051
nixos-vm> elastic-arm-2c90f239: building spi8fcy63j1bm5xsmgg821lvwky14f06-nixos-vm.drv
building '/nix/store/9ips75z7cdxnnvc6kf51dgk8y5ymdd8r-driverConfiguration.json.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=20&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/9ips75z7cdxnnvc6kf51dgk8y5ymdd8r-driverConfiguration.json.drv' on farm.numtide.com:50051
driverConfiguration.json> elastic-arm-2c90f239: building 9ips75z7cdxnnvc6kf51dgk8y5ymdd8r-driverConfiguration.json.drv
driverConfiguration.json> structuredAttrs is enabled
building '/nix/store/n1aaid4js7k86k0warsnyjpflpp4qmy2-nixos-test-driver-horae-e2e-oidc.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=20&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/n1aaid4js7k86k0warsnyjpflpp4qmy2-nixos-test-driver-horae-e2e-oidc.drv' on farm.numtide.com:50051
nixos-test-driver-horae-e2e-oidc> elastic-arm-2c90f239: building n1aaid4js7k86k0warsnyjpflpp4qmy2-nixos-test-driver-horae-e2e-oidc.drv
nixos-test-driver-horae-e2e-oidc> Running type check (enable/disable: config.skipTypeCheck)
nixos-test-driver-horae-e2e-oidc> See https://nixos.org/manual/nixos/stable/#test-opt-skipTypeCheck
nixos-test-driver-horae-e2e-oidc> All checks passed!
nixos-test-driver-horae-e2e-oidc> Linting test script (enable/disable: config.skipLint)
nixos-test-driver-horae-e2e-oidc> See https://nixos.org/manual/nixos/stable/#test-opt-skipLint
nixos-test-driver-horae-e2e-oidc> All checks passed!
building '/nix/store/gjywx06fh5svsllp19qbybxl0v43rphj-vm-test-run-horae-e2e-oidc.drv' on 'grpc://farm.numtide.com:50051?connect-timeout=20&system=aarch64-linux&token-file=/run/nix-farm-client/farm-token'
building '/nix/store/gjywx06fh5svsllp19qbybxl0v43rphj-vm-test-run-horae-e2e-oidc.drv' on farm.numtide.com:50051
vm-test-run-horae-e2e-oidc> elastic-arm-2c90f239: building gjywx06fh5svsllp19qbybxl0v43rphj-vm-test-run-horae-e2e-oidc.drv
vm-test-run-horae-e2e-oidc> Machine state will be reset. To keep it, pass --keep-machine-state
vm-test-run-horae-e2e-oidc> start all VLans
vm-test-run-horae-e2e-oidc> (finished: start all VLans, in 0.00 seconds)
vm-test-run-horae-e2e-oidc> Test will time out and terminate in 3600 seconds
vm-test-run-horae-e2e-oidc> run the VM test script
vm-test-run-horae-e2e-oidc> additionally exposed symbols:
vm-test-run-horae-e2e-oidc>     server,
vm-test-run-horae-e2e-oidc>     vlan1,
vm-test-run-horae-e2e-oidc>     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
vm-test-run-horae-e2e-oidc> server: starting vm
vm-test-run-horae-e2e-oidc> server: QEMU running (pid 12)
vm-test-run-horae-e2e-oidc> server # Disk image does not exist, creating the virtualisation disk image...
vm-test-run-horae-e2e-oidc> server # Formatting '/build/vm-state-server/tmp.iSgnEmF1se', fmt=raw size=1073741824
vm-test-run-horae-e2e-oidc> server # mke2fs 1.47.4 (6-Mar-2025)
vm-test-run-horae-e2e-oidc> server # Discarding device blocks:      0/262144             done
vm-test-run-horae-e2e-oidc> server # Creating filesystem with 262144 4k blocks and 65536 inodes
vm-test-run-horae-e2e-oidc> server # Filesystem UUID: 2241a54f-b3d1-4ee5-bb43-d0b4c5a958d0
vm-test-run-horae-e2e-oidc> server # Superblock backups stored on blocks:
vm-test-run-horae-e2e-oidc> server # 	32768, 98304, 163840, 229376
vm-test-run-horae-e2e-oidc> server # 
vm-test-run-horae-e2e-oidc> server # Allocating group tables: 0/8   done
vm-test-run-horae-e2e-oidc> server # Writing inode tables: 0/8   done
vm-test-run-horae-e2e-oidc> server # Creating journal (8192 blocks): done
vm-test-run-horae-e2e-oidc> server # Writing superblocks and filesystem accounting information: 0/8   done
vm-test-run-horae-e2e-oidc> server # 
vm-test-run-horae-e2e-oidc> server # Virtualisation disk image created.
vm-test-run-horae-e2e-oidc> server # Creating Nix store image...
vm-test-run-horae-e2e-oidc> server # Created Nix store image.
vm-test-run-horae-e2e-oidc> server # qemu-system-aarch64: Could not access KVM kernel module: No such file or directory
vm-test-run-horae-e2e-oidc> server # qemu-system-aarch64: failed to initialize kvm: No such file or directory
vm-test-run-horae-e2e-oidc> server # qemu-system-aarch64: falling back to tcg
vm-test-run-horae-e2e-oidc> server # [    0.000000] Booting Linux on physical CPU 0x0000000000 [0x000f0510]
vm-test-run-horae-e2e-oidc> server # [    0.000000] Linux version 6.18.38 (nixbld@localhost) (gcc (GCC) 15.2.0, GNU ld (GNU Binutils) 2.46) #1-NixOS SMP PREEMPT Sat Jul  4 11:44:22 UTC 2026
vm-test-run-horae-e2e-oidc> server # [    0.000000] KASLR enabled
vm-test-run-horae-e2e-oidc> server # [    0.000000] random: crng init done
vm-test-run-horae-e2e-oidc> server # [    0.000000] Machine model: linux,dummy-virt
vm-test-run-horae-e2e-oidc> server # [    0.000000] efi: UEFI not found.
vm-test-run-horae-e2e-oidc> server # [    0.000000] OF: reserved mem: Reserved memory: No reserved-memory node in the DT
vm-test-run-horae-e2e-oidc> server # [    0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x000000007fffffff]
vm-test-run-horae-e2e-oidc> server # [    0.000000] NODE_DATA(0) allocated [mem 0x7fc06740-0x7fc09ebf]
vm-test-run-horae-e2e-oidc> server # [    0.000000] Zone ranges:
vm-test-run-horae-e2e-oidc> server # [    0.000000]   DMA      [mem 0x0000000040000000-0x000000007fffffff]
vm-test-run-horae-e2e-oidc> server # [    0.000000]   DMA32    empty
vm-test-run-horae-e2e-oidc> server # [    0.000000]   Normal   empty
vm-test-run-horae-e2e-oidc> server # [    0.000000]   Device   empty
vm-test-run-horae-e2e-oidc> server # [    0.000000] Movable zone start for each node
vm-test-run-horae-e2e-oidc> server # [    0.000000] Early memory node ranges
vm-test-run-horae-e2e-oidc> server # [    0.000000]   node   0: [mem 0x0000000040000000-0x000000007fffffff]
vm-test-run-horae-e2e-oidc> server # [    0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x000000007fffffff]
vm-test-run-horae-e2e-oidc> server # [    0.000000] cma: Reserved 32 MiB at 0x000000007ca00000
vm-test-run-horae-e2e-oidc> server # [    0.000000] psci: probing for conduit method from DT.
vm-test-run-horae-e2e-oidc> server # [    0.000000] psci: PSCIv1.1 detected in firmware.
vm-test-run-horae-e2e-oidc> server # [    0.000000] psci: Using standard PSCI v0.2 function IDs
vm-test-run-horae-e2e-oidc> server # [    0.000000] psci: Trusted OS migration not required
vm-test-run-horae-e2e-oidc> server # [    0.000000] psci: SMC Calling Convention v1.0
vm-test-run-horae-e2e-oidc> server # [    0.000000] percpu: Embedded 76 pages/cpu s186392 r8192 d116712 u311296
vm-test-run-horae-e2e-oidc> server # [    0.000000] Detected PIPT I-cache on CPU0
vm-test-run-horae-e2e-oidc> server # [    0.000000] CPU features: detected: Address authentication (IMP DEF algorithm)
vm-test-run-horae-e2e-oidc> server # [    0.000000] CPU features: detected: GICv3 CPU interface
vm-test-run-horae-e2e-oidc> server # [    0.000000] CPU features: detected: HCRX_EL2 register
vm-test-run-horae-e2e-oidc> server # [    0.000000] CPU features: detected: Stage-1 Permission Indirection Extension (S1PIE)
vm-test-run-horae-e2e-oidc> server # [    0.000000] CPU features: detected: 52-bit Virtual Addressing (LPA2)
vm-test-run-horae-e2e-oidc> server # [    0.000000] CPU features: detected: Spectre-v4
vm-test-run-horae-e2e-oidc> server # [    0.000000] alternatives: applying boot alternatives
vm-test-run-horae-e2e-oidc> server # [    0.000000] Kernel command line: console=ttyAMA0 console=tty0 panic=1 boot.panic_on_fail clocksource=acpi_pm root=fstab loglevel=7 net.ifnames=0 lsm=landlock,yama,bpf init=/nix/store/whgc6x44bw1l966rzs1hldz2nmxhk2hd-nixos-system-server-test/init regInfo=/nix/store/dflfxzln02rs3spb91bdz9ygyiz0hdj5-closure-info/registration console=ttyAMA0,115200n8 console=tty0
vm-test-run-horae-e2e-oidc> server # [    0.000000] Unknown kernel command line parameters "regInfo=/nix/store/dflfxzln02rs3spb91bdz9ygyiz0hdj5-closure-info/registration", will be passed to user space.
vm-test-run-horae-e2e-oidc> server # [    0.000000] printk: log buffer data + meta data: 131072 + 458752 = 589824 bytes
vm-test-run-horae-e2e-oidc> server # [    0.000000] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    0.000000] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    0.000000] software IO TLB: SWIOTLB bounce buffer size adjusted to 1MB
vm-test-run-horae-e2e-oidc> server # [    0.000000] software IO TLB: area num 1.
vm-test-run-horae-e2e-oidc> server # [    0.000000] software IO TLB: mapped [mem 0x000000007c732000-0x000000007c832000] (1MB)
vm-test-run-horae-e2e-oidc> server # [    0.000000] Fallback order for Node 0: 0
vm-test-run-horae-e2e-oidc> server # [    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 262144
vm-test-run-horae-e2e-oidc> server # [    0.000000] Policy zone: DMA
vm-test-run-horae-e2e-oidc> server # [    0.000000] mem auto-init: stack:all(zero), heap alloc:on, heap free:off
vm-test-run-horae-e2e-oidc> server # [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
vm-test-run-horae-e2e-oidc> server # [    0.000000] allocated 2097152 bytes of page_ext
vm-test-run-horae-e2e-oidc> server # [    0.000000] ftrace: allocating 74713 entries in 292 pages
vm-test-run-horae-e2e-oidc> server # [    0.000000] ftrace: allocated 292 pages with 3 groups
vm-test-run-horae-e2e-oidc> server # [    0.000000] rcu: Hierarchical RCU implementation.
vm-test-run-horae-e2e-oidc> server # [    0.000000] rcu: 	RCU event tracing is enabled.
vm-test-run-horae-e2e-oidc> server # [    0.000000] rcu: 	RCU restricting CPUs from NR_CPUS=384 to nr_cpu_ids=1.
vm-test-run-horae-e2e-oidc> server # [    0.000000] 	Trampoline variant of Tasks RCU enabled.
vm-test-run-horae-e2e-oidc> server # [    0.000000] 	Rude variant of Tasks RCU enabled.
vm-test-run-horae-e2e-oidc> server # [    0.000000] 	Tracing variant of Tasks RCU enabled.
vm-test-run-horae-e2e-oidc> server # [    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
vm-test-run-horae-e2e-oidc> server # [    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
vm-test-run-horae-e2e-oidc> server # [    0.000000] RCU Tasks: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=1.
vm-test-run-horae-e2e-oidc> server # [    0.000000] RCU Tasks Rude: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=1.
vm-test-run-horae-e2e-oidc> server # [    0.000000] RCU Tasks Trace: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=1.
vm-test-run-horae-e2e-oidc> server # [    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
vm-test-run-horae-e2e-oidc> server # [    0.000000] GICv3: 256 SPIs implemented
vm-test-run-horae-e2e-oidc> server # [    0.000000] GICv3: 0 Extended SPIs implemented
vm-test-run-horae-e2e-oidc> server # [    0.000000] Root IRQ handler: gic_handle_irq
vm-test-run-horae-e2e-oidc> server # [    0.000000] GICv3: GICv3 features: 16 PPIs
vm-test-run-horae-e2e-oidc> server # [    0.000000] GICv3: GICD_CTLR.DS=1, SCR_EL3.FIQ=0
vm-test-run-horae-e2e-oidc> server # [    0.000000] GICv3: CPU0: found redistributor 0 region 0:0x00000000080a0000
vm-test-run-horae-e2e-oidc> server # [    0.000000] ITS [mem 0x08080000-0x0809ffff]
vm-test-run-horae-e2e-oidc> server # [    0.000000] ITS@0x0000000008080000: allocated 8192 Devices @44ce0000 (indirect, esz 8, psz 64K, shr 1)
vm-test-run-horae-e2e-oidc> server # [    0.000000] ITS@0x0000000008080000: allocated 8192 Interrupt Collections @44cf0000 (flat, esz 8, psz 64K, shr 1)
vm-test-run-horae-e2e-oidc> server # [    0.000000] GICv3: using LPI property table @0x0000000044d00000
vm-test-run-horae-e2e-oidc> server # [    0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000044d10000
vm-test-run-horae-e2e-oidc> server # [    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
vm-test-run-horae-e2e-oidc> server # [    0.000000] arch_timer: cp15 timer running at 1000.00MHz (virt).
vm-test-run-horae-e2e-oidc> server # [    0.000000] clocksource: arch_sys_counter: mask: 0x1fffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
vm-test-run-horae-e2e-oidc> server # [    0.000085] sched_clock: 61 bits at 1000MHz, resolution 1ns, wraps every 4398046511103ns
vm-test-run-horae-e2e-oidc> server # [    0.006070] kfence: initialized - using 2097152 bytes for 255 objects at 0x(____ptrval____)-0x(____ptrval____)
vm-test-run-horae-e2e-oidc> server # [    0.034056] Console: colour dummy device 80x25
vm-test-run-horae-e2e-oidc> server # [    0.037834] printk: legacy console [tty0] enabled
vm-test-run-horae-e2e-oidc> server # [    0.054421] Calibrating delay loop (skipped), value calculated using timer frequency.. 2000.00 BogoMIPS (lpj=4000000)
vm-test-run-horae-e2e-oidc> server # [    0.055485] pid_max: default: 32768 minimum: 301
vm-test-run-horae-e2e-oidc> server # [    0.063542] LSM: initializing lsm=capability,landlock,yama,bpf,ima
vm-test-run-horae-e2e-oidc> server # [    0.066726] landlock: Up and running.
vm-test-run-horae-e2e-oidc> server # [    0.066914] Yama: becoming mindful.
vm-test-run-horae-e2e-oidc> server # [    0.069972] LSM support for eBPF active
vm-test-run-horae-e2e-oidc> server # [    0.076110] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    0.076413] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    0.149372] cacheinfo: Unable to detect cache hierarchy for CPU 0
vm-test-run-horae-e2e-oidc> server # [    0.180484] rcu: Hierarchical SRCU implementation.
vm-test-run-horae-e2e-oidc> server # [    0.180698] rcu: 	Max phase no-delay instances is 1000.
vm-test-run-horae-e2e-oidc> server # [    0.201917] fsl-mc MSI: its@8080000 domain created
vm-test-run-horae-e2e-oidc> server # [    0.206412] EFI services will not be available.
vm-test-run-horae-e2e-oidc> server # [    0.209801] smp: Bringing up secondary CPUs ...
vm-test-run-horae-e2e-oidc> server # [    0.211185] smp: Brought up 1 node, 1 CPU
vm-test-run-horae-e2e-oidc> server # [    0.211320] SMP: Total of 1 processors activated.
vm-test-run-horae-e2e-oidc> server # [    0.211421] CPU: All CPU(s) started at EL1
vm-test-run-horae-e2e-oidc> server # [    0.212094] CPU features: detected: Branch Target Identification
vm-test-run-horae-e2e-oidc> server # [    0.212235] CPU features: detected: 32-bit EL0 Support
vm-test-run-horae-e2e-oidc> server # [    0.212310] CPU features: detected: 32-bit EL1 Support
vm-test-run-horae-e2e-oidc> server # [    0.212374] CPU features: detected: ARMv8.4 Translation Table Level
vm-test-run-horae-e2e-oidc> server # [    0.212456] CPU features: detected: Instruction cache invalidation not required for I/D coherence
vm-test-run-horae-e2e-oidc> server # [    0.212552] CPU features: detected: Data cache clean to the PoU not required for I/D coherence
vm-test-run-horae-e2e-oidc> server # [    0.212684] CPU features: detected: Common not Private translations
vm-test-run-horae-e2e-oidc> server # [    0.212783] CPU features: detected: CRC32 instructions
vm-test-run-horae-e2e-oidc> server # [    0.212854] CPU features: detected: Data cache clean to Point of Deep Persistence
vm-test-run-horae-e2e-oidc> server # [    0.212928] CPU features: detected: Data cache clean to Point of Persistence
vm-test-run-horae-e2e-oidc> server # [    0.212995] CPU features: detected: Data independent timing control (DIT)
vm-test-run-horae-e2e-oidc> server # [    0.213060] CPU features: detected: E0PD
vm-test-run-horae-e2e-oidc> server # [    0.213112] CPU features: detected: Enhanced Counter Virtualization
vm-test-run-horae-e2e-oidc> server # [    0.213174] CPU features: detected: Enhanced Counter Virtualization (CNTPOFF)
vm-test-run-horae-e2e-oidc> server # [    0.213241] CPU features: detected: Enhanced Privileged Access Never
vm-test-run-horae-e2e-oidc> server # [    0.213303] CPU features: detected: Enhanced Virtualization Traps
vm-test-run-horae-e2e-oidc> server # [    0.213379] CPU features: detected: Fine Grained Traps
vm-test-run-horae-e2e-oidc> server # [    0.213463] CPU features: detected: Guarded Control Stack (GCS)
vm-test-run-horae-e2e-oidc> server # [    0.216071] CPU features: detected: Generic authentication (IMP DEF algorithm)
vm-test-run-horae-e2e-oidc> server # [    0.216380] CPU features: detected: RCpc load-acquire (LDAPR)
vm-test-run-horae-e2e-oidc> server # [    0.216590] CPU features: detected: 52-bit Virtual Addressing for KVM (LPA2)
vm-test-run-horae-e2e-oidc> server # [    0.216693] CPU features: detected: LSE atomic instructions
vm-test-run-horae-e2e-oidc> server # [    0.216773] CPU features: detected: Memory Copy and Memory Set instructions
vm-test-run-horae-e2e-oidc> server # [    0.216859] CPU features: detected: Privileged Access Never
vm-test-run-horae-e2e-oidc> server # [    0.217028] CPU features: detected: PMUv3
vm-test-run-horae-e2e-oidc> server # [    0.217097] CPU features: detected: SCTLR2
vm-test-run-horae-e2e-oidc> server # [    0.217151] CPU features: detected: RAS Extension Support
vm-test-run-horae-e2e-oidc> server # [    0.217288] CPU features: detected: RASv1p1 Extension Support
vm-test-run-horae-e2e-oidc> server # [    0.217351] CPU features: detected: Random Number Generator
vm-test-run-horae-e2e-oidc> server # [    0.217411] CPU features: detected: Speculation barrier (SB)
vm-test-run-horae-e2e-oidc> server # [    0.217471] CPU features: detected: Stage-2 Force Write-Back
vm-test-run-horae-e2e-oidc> server # [    0.217533] CPU features: detected: Trap EL0 IMPLEMENTATION DEFINED functionality
vm-test-run-horae-e2e-oidc> server # [    0.217672] CPU features: detected: TLB range maintenance instructions
vm-test-run-horae-e2e-oidc> server # [    0.217803] CPU features: detected: WFx with timeout
vm-test-run-horae-e2e-oidc> server # [    0.218818] CPU features: detected: Scalable Matrix Extension
vm-test-run-horae-e2e-oidc> server # [    0.218901] CPU features: detected: FA64
vm-test-run-horae-e2e-oidc> server # [    0.218955] CPU features: detected: SME2
vm-test-run-horae-e2e-oidc> server # [    0.219008] CPU features: detected: Speculative Store Bypassing Safe (SSBS)
vm-test-run-horae-e2e-oidc> server # [    0.219074] CPU features: detected: Scalable Vector Extension
vm-test-run-horae-e2e-oidc> server # [    0.238872] alternatives: applying system-wide alternatives
vm-test-run-horae-e2e-oidc> server # [    0.267759] CPU features: detected: Hardware dirty bit management on CPU0
vm-test-run-horae-e2e-oidc> server # [    0.269329] SVE: maximum available vector length 256 bytes per vector
vm-test-run-horae-e2e-oidc> server # [    0.269517] SVE: default vector length 64 bytes per vector
vm-test-run-horae-e2e-oidc> server # [    0.272831] SME: minimum available vector length 16 bytes per vector
vm-test-run-horae-e2e-oidc> server # [    0.273043] SME: maximum available vector length 256 bytes per vector
vm-test-run-horae-e2e-oidc> server # [    0.273168] SME: default vector length 32 bytes per vector
vm-test-run-horae-e2e-oidc> server # [    0.305885] Memory: 891000K/1048576K available (24384K kernel code, 7086K rwdata, 26324K rodata, 4736K init, 1102K bss, 116312K reserved, 32768K cma-reserved)
vm-test-run-horae-e2e-oidc> server # [    0.363614] devtmpfs: initialized
vm-test-run-horae-e2e-oidc> server # [    0.436348] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
vm-test-run-horae-e2e-oidc> server # [    0.437866] posixtimers hash table entries: 512 (order: 1, 8192 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    0.438476] futex hash table entries: 256 (16384 bytes on 1 NUMA nodes, total 16 KiB, linear).
vm-test-run-horae-e2e-oidc> server # [    0.446707] 2G module region forced by RANDOMIZE_MODULE_REGION_FULL
vm-test-run-horae-e2e-oidc> server # [    0.446938] 0 pages in range for non-PLT usage
vm-test-run-horae-e2e-oidc> server # [    0.447035] 508320 pages in range for PLT usage
vm-test-run-horae-e2e-oidc> server # [    0.454343] pinctrl core: initialized pinctrl subsystem
vm-test-run-horae-e2e-oidc> server # [    0.482053] DMI not present or invalid.
vm-test-run-horae-e2e-oidc> server # [    0.519390] NET: Registered PF_NETLINK/PF_ROUTE protocol family
vm-test-run-horae-e2e-oidc> server # [    0.545459] DMA: preallocated 128 KiB GFP_KERNEL pool for atomic allocations
vm-test-run-horae-e2e-oidc> server # [    0.549060] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
vm-test-run-horae-e2e-oidc> server # [    0.552992] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
vm-test-run-horae-e2e-oidc> server # [    0.553906] audit: initializing netlink subsys (disabled)
vm-test-run-horae-e2e-oidc> server # [    0.562897] audit: type=2000 audit(0.460:1): state=initialized audit_enabled=0 res=1
vm-test-run-horae-e2e-oidc> server # [    0.575711] thermal_sys: Registered thermal governor 'fair_share'
vm-test-run-horae-e2e-oidc> server # [    0.575905] thermal_sys: Registered thermal governor 'bang_bang'
vm-test-run-horae-e2e-oidc> server # [    0.576037] thermal_sys: Registered thermal governor 'step_wise'
vm-test-run-horae-e2e-oidc> server # [    0.576105] thermal_sys: Registered thermal governor 'user_space'
vm-test-run-horae-e2e-oidc> server # [    0.576173] thermal_sys: Registered thermal governor 'power_allocator'
vm-test-run-horae-e2e-oidc> server # [    0.577334] cpuidle: using governor ladder
vm-test-run-horae-e2e-oidc> server # [    0.577816] cpuidle: using governor menu
vm-test-run-horae-e2e-oidc> server # [    0.582773] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
vm-test-run-horae-e2e-oidc> server # [    0.586265] ASID allocator initialised with 65536 entries
vm-test-run-horae-e2e-oidc> server # [    0.611393] Serial: AMBA PL011 UART driver
vm-test-run-horae-e2e-oidc> server # [    0.761135] 9000000.pl011: ttyAMA0 at MMIO 0x9000000 (irq = 13, base_baud = 0) is a PL011 rev1
vm-test-run-horae-e2e-oidc> server # [    0.766493] printk: console [ttyAMA0] enabled
vm-test-run-horae-e2e-oidc> server # [    0.940416] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages
vm-test-run-horae-e2e-oidc> server # [    0.940851] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page
vm-test-run-horae-e2e-oidc> server # [    0.941007] HugeTLB: registered 32.0 MiB page size, pre-allocated 0 pages
vm-test-run-horae-e2e-oidc> server # [    0.941103] HugeTLB: 0 KiB vmemmap can be freed for a 32.0 MiB page
vm-test-run-horae-e2e-oidc> server # [    0.941196] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages
vm-test-run-horae-e2e-oidc> server # [    0.941286] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page
vm-test-run-horae-e2e-oidc> server # [    0.941406] HugeTLB: registered 64.0 KiB page size, pre-allocated 0 pages
vm-test-run-horae-e2e-oidc> server # [    0.941520] HugeTLB: 0 KiB vmemmap can be freed for a 64.0 KiB page
vm-test-run-horae-e2e-oidc> server # [    1.015884] fbcon: Taking over console
vm-test-run-horae-e2e-oidc> server # [    1.016663] ACPI: Interpreter disabled.
vm-test-run-horae-e2e-oidc> server # [    1.066138] iommu: Default domain type: Translated
vm-test-run-horae-e2e-oidc> server # [    1.066484] iommu: DMA domain TLB invalidation policy: strict mode
vm-test-run-horae-e2e-oidc> server # [    1.084246] SCSI subsystem initialized
vm-test-run-horae-e2e-oidc> server # [    1.091490] usbcore: registered new interface driver usbfs
vm-test-run-horae-e2e-oidc> server # [    1.101295] usbcore: registered new interface driver hub
vm-test-run-horae-e2e-oidc> server # [    1.102127] usbcore: registered new device driver usb
vm-test-run-horae-e2e-oidc> server # [    1.118155] pps_core: LinuxPPS API ver. 1 registered
vm-test-run-horae-e2e-oidc> server # [    1.118481] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
vm-test-run-horae-e2e-oidc> server # [    1.118865] PTP clock support registered
vm-test-run-horae-e2e-oidc> server # [    1.121790] EDAC MC: Ver: 3.0.0
vm-test-run-horae-e2e-oidc> server # [    1.135147] scmi_core: SCMI protocol bus registered
vm-test-run-horae-e2e-oidc> server # [    1.152832] FPGA manager framework
vm-test-run-horae-e2e-oidc> server # [    1.210226] vgaarb: loaded
vm-test-run-horae-e2e-oidc> server # [    1.227703] clocksource: Switched to clocksource arch_sys_counter
vm-test-run-horae-e2e-oidc> server # [    1.461811] VFS: Disk quotas dquot_6.6.0
vm-test-run-horae-e2e-oidc> server # [    1.462574] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
vm-test-run-horae-e2e-oidc> server # [    1.474736] netfs: FS-Cache loaded
vm-test-run-horae-e2e-oidc> server # [    1.478981] pnp: PnP ACPI: disabled
vm-test-run-horae-e2e-oidc> server # [    1.557090] NET: Registered PF_INET protocol family
vm-test-run-horae-e2e-oidc> server # [    1.560516] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    1.807048] tcp_listen_portaddr_hash hash table entries: 512 (order: 1, 8192 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    1.808986] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    1.809425] TCP established hash table entries: 8192 (order: 4, 65536 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    1.810046] TCP bind hash table entries: 8192 (order: 6, 262144 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    1.810505] TCP: Hash tables configured (established 8192 bind 8192)
vm-test-run-horae-e2e-oidc> server # [    1.817488] MPTCP token hash table entries: 1024 (order: 3, 24576 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    1.818437] UDP hash table entries: 512 (order: 3, 32768 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    1.819138] UDP-Lite hash table entries: 512 (order: 3, 32768 bytes, linear)
vm-test-run-horae-e2e-oidc> server # [    1.825085] NET: Registered PF_UNIX/PF_LOCAL protocol family
vm-test-run-horae-e2e-oidc> server # [    1.826297] NET: Registered PF_XDP protocol family
vm-test-run-horae-e2e-oidc> server # [    1.826882] PCI: CLS 0 bytes, default 64
vm-test-run-horae-e2e-oidc> server # [    1.842011] Trying to unpack rootfs image as initramfs...
vm-test-run-horae-e2e-oidc> server # [    1.852259] kvm [1]: HYP mode not available
vm-test-run-horae-e2e-oidc> server # [    2.564518] Initialise system trusted keyrings
vm-test-run-horae-e2e-oidc> server # [    2.569049] workingset: timestamp_bits=42 max_order=18 bucket_order=0
vm-test-run-horae-e2e-oidc> server # [    2.602349] squashfs: version 4.0 (2009/01/31) Phillip Lougher
vm-test-run-horae-e2e-oidc> server # [    2.613033] 9p: Installing v9fs 9p2000 file system support
vm-test-run-horae-e2e-oidc> server # [    2.900925] Key type asymmetric registered
vm-test-run-horae-e2e-oidc> server # [    2.901535] Asymmetric key parser 'x509' registered
vm-test-run-horae-e2e-oidc> server # [    2.902570] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 242)
vm-test-run-horae-e2e-oidc> server # [    2.906658] io scheduler mq-deadline registered
vm-test-run-horae-e2e-oidc> server # [    2.907043] io scheduler kyber registered
vm-test-run-horae-e2e-oidc> server # [    3.088484] pl061_gpio 9030000.pl061: PL061 GPIO chip registered
vm-test-run-horae-e2e-oidc> server # [    3.116201] ledtrig-cpu: registered to indicate activity on CPUs
vm-test-run-horae-e2e-oidc> server # [    3.134852] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges:
vm-test-run-horae-e2e-oidc> server # [    3.140967] pci-host-generic 4010000000.pcie:       IO 0x003eff0000..0x003effffff -> 0x0000000000
vm-test-run-horae-e2e-oidc> server # [    3.142288] pci-host-generic 4010000000.pcie:      MEM 0x0010000000..0x003efeffff -> 0x0010000000
vm-test-run-horae-e2e-oidc> server # [    3.142650] pci-host-generic 4010000000.pcie:      MEM 0x8000000000..0xffffffffff -> 0x8000000000
vm-test-run-horae-e2e-oidc> server # [    3.153003] pci-host-generic 4010000000.pcie: Memory resource size exceeds max for 32 bits
vm-test-run-horae-e2e-oidc> server # [    3.154391] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]
vm-test-run-horae-e2e-oidc> server # [    3.166980] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00
vm-test-run-horae-e2e-oidc> server # [    3.169425] pci_bus 0000:00: root bus resource [bus 00-ff]
vm-test-run-horae-e2e-oidc> server # [    3.169886] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
vm-test-run-horae-e2e-oidc> server # [    3.170097] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff]
vm-test-run-horae-e2e-oidc> server # [    3.170218] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff]
vm-test-run-horae-e2e-oidc> server # [    3.177596] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.195281] pci 0000:00:01.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.208709] pci 0000:00:01.0: BAR 0 [io  0x0000-0x001f]
vm-test-run-horae-e2e-oidc> server # [    3.209150] pci 0000:00:01.0: BAR 1 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.209335] pci 0000:00:01.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
vm-test-run-horae-e2e-oidc> server # [    3.209584] pci 0000:00:01.0: ROM [mem 0x00000000-0x0003ffff pref]
vm-test-run-horae-e2e-oidc> server # [    3.214080] pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.214455] pci 0000:00:02.0: BAR 0 [io  0x0000-0x001f]
vm-test-run-horae-e2e-oidc> server # [    3.214588] pci 0000:00:02.0: BAR 1 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.214703] pci 0000:00:02.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
vm-test-run-horae-e2e-oidc> server # [    3.220585] pci 0000:00:03.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.221073] pci 0000:00:03.0: BAR 0 [io  0x0000-0x001f]
vm-test-run-horae-e2e-oidc> server # [    3.221226] pci 0000:00:03.0: BAR 1 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.221346] pci 0000:00:03.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
vm-test-run-horae-e2e-oidc> server # [    3.222987] pci 0000:00:04.0: [1af4:1009] type 00 class 0x000200 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.223310] pci 0000:00:04.0: BAR 0 [io  0x0000-0x001f]
vm-test-run-horae-e2e-oidc> server # [    3.232422] pci 0000:00:04.0: BAR 1 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.232684] pci 0000:00:04.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
vm-test-run-horae-e2e-oidc> server # [    3.234543] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.234872] pci 0000:00:05.0: BAR 0 [io  0x0000-0x007f]
vm-test-run-horae-e2e-oidc> server # [    3.235013] pci 0000:00:05.0: BAR 1 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.235132] pci 0000:00:05.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
vm-test-run-horae-e2e-oidc> server # [    3.245355] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.245833] pci 0000:00:06.0: BAR 0 [io  0x0000-0x007f]
vm-test-run-horae-e2e-oidc> server # [    3.245989] pci 0000:00:06.0: BAR 1 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.246310] pci 0000:00:06.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
vm-test-run-horae-e2e-oidc> server # [    3.250412] pci 0000:00:07.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.250855] pci 0000:00:07.0: BAR 0 [io  0x0000-0x001f]
vm-test-run-horae-e2e-oidc> server # [    3.251002] pci 0000:00:07.0: BAR 1 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.251119] pci 0000:00:07.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
vm-test-run-horae-e2e-oidc> server # [    3.251235] pci 0000:00:07.0: ROM [mem 0x00000000-0x0003ffff pref]
vm-test-run-horae-e2e-oidc> server # [    3.261671] pci 0000:00:08.0: [1af4:1050] type 00 class 0x038000 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.262135] pci 0000:00:08.0: BAR 1 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.262287] pci 0000:00:08.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
vm-test-run-horae-e2e-oidc> server # [    3.266275] pci 0000:00:09.0: [1af4:1052] type 00 class 0x090000 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.266794] pci 0000:00:09.0: BAR 1 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.266972] pci 0000:00:09.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
vm-test-run-horae-e2e-oidc> server # [    3.282404] pci 0000:00:0a.0: [8086:24cd] type 00 class 0x0c0320 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.282847] pci 0000:00:0a.0: BAR 0 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.287877] pci 0000:00:0b.0: [1af4:1003] type 00 class 0x078000 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.288375] pci 0000:00:0b.0: BAR 0 [io  0x0000-0x003f]
vm-test-run-horae-e2e-oidc> server # [    3.288534] pci 0000:00:0b.0: BAR 1 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.288650] pci 0000:00:0b.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
vm-test-run-horae-e2e-oidc> server # [    3.290202] pci 0000:00:0c.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint
vm-test-run-horae-e2e-oidc> server # [    3.290522] pci 0000:00:0c.0: BAR 0 [io  0x0000-0x001f]
vm-test-run-horae-e2e-oidc> server # [    3.290647] pci 0000:00:0c.0: BAR 1 [mem 0x00000000-0x00000fff]
vm-test-run-horae-e2e-oidc> server # [    3.290786] pci 0000:00:0c.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]
vm-test-run-horae-e2e-oidc> server # [    3.311784] pci 0000:00:01.0: ROM [mem 0x10000000-0x1003ffff pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.312509] pci 0000:00:07.0: ROM [mem 0x10040000-0x1007ffff pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.320245] pci 0000:00:01.0: BAR 4 [mem 0x8000000000-0x8000003fff 64bit pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.321025] pci 0000:00:02.0: BAR 4 [mem 0x8000004000-0x8000007fff 64bit pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.321323] pci 0000:00:03.0: BAR 4 [mem 0x8000008000-0x800000bfff 64bit pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.321508] pci 0000:00:04.0: BAR 4 [mem 0x800000c000-0x800000ffff 64bit pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.321673] pci 0000:00:05.0: BAR 4 [mem 0x8000010000-0x8000013fff 64bit pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.321888] pci 0000:00:06.0: BAR 4 [mem 0x8000014000-0x8000017fff 64bit pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.322065] pci 0000:00:07.0: BAR 4 [mem 0x8000018000-0x800001bfff 64bit pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.322226] pci 0000:00:08.0: BAR 4 [mem 0x800001c000-0x800001ffff 64bit pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.322390] pci 0000:00:09.0: BAR 4 [mem 0x8000020000-0x8000023fff 64bit pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.322557] pci 0000:00:0b.0: BAR 4 [mem 0x8000024000-0x8000027fff 64bit pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.322822] pci 0000:00:0c.0: BAR 4 [mem 0x8000028000-0x800002bfff 64bit pref]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.323069] pci 0000:00:01.0: BAR 1 [mem 0x10080000-0x10080fff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.323233] pci 0000:00:02.0: BAR 1 [mem 0x10081000-0x10081fff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.340246] pci 0000:00:03.0: BAR 1 [mem 0x10082000-0x10082fff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.340502] pci 0000:00:04.0: BAR 1 [mem 0x10083000-0x10083fff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.340644] pci 0000:00:05.0: BAR 1 [mem 0x10084000-0x10084fff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.340824] pci 0000:00:06.0: BAR 1 [mem 0x10085000-0x10085fff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.340977] pci 0000:00:07.0: BAR 1 [mem 0x10086000-0x10086fff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.341111] pci 0000:00:08.0: BAR 1 [mem 0x10087000-0x10087fff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.341243] pci 0000:00:09.0: BAR 1 [mem 0x10088000-0x10088fff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.341575] pci 0000:00:0a.0: BAR 0 [mem 0x10089000-0x10089fff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.341741] pci 0000:00:0b.0: BAR 1 [mem 0x1008a000-0x1008afff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.341904] pci 0000:00:0c.0: BAR 1 [mem 0x1008b000-0x1008bfff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.342075] pci 0000:00:05.0: BAR 0 [io  0x1000-0x107f]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.342262] pci 0000:00:06.0: BAR 0 [io  0x1080-0x10ff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.342407] pci 0000:00:0b.0: BAR 0 [io  0x1100-0x113f]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.342537] pci 0000:00:01.0: BAR 0 [io  0x1140-0x115f]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.342667] pci 0000:00:02.0: BAR 0 [io  0x1160-0x117f]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.342848] pci 0000:00:03.0: BAR 0 [io  0x1180-0x119f]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.342991] pci 0000:00:04.0: BAR 0 [io  0x11a0-0x11bf]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.343119] pci 0000:00:07.0: BAR 0 [io  0x11c0-0x11df]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.343243] pci 0000:00:0c.0: BAR 0 [io  0x11e0-0x11ff]: assigned
vm-test-run-horae-e2e-oidc> server # [    3.358382] pci_bus 0000:00: resource 4 [io  0x0000-0xffff]
vm-test-run-horae-e2e-oidc> server # [    3.358715] pci_bus 0000:00: resource 5 [mem 0x10000000-0x3efeffff]
vm-test-run-horae-e2e-oidc> server # [    3.358902] pci_bus 0000:00: resource 6 [mem 0x8000000000-0xffffffffff]
vm-test-run-horae-e2e-oidc> server # [    3.364971] pci 0000:00:0a.0: enabling device (0000 -> 0002)
vm-test-run-horae-e2e-oidc> server # [    3.376329] pci 0000:00:0a.0: quirk_usb_early_handoff+0x0/0xa60 took 11735 usecs
vm-test-run-horae-e2e-oidc> server # [    3.773095] virtio-pci 0000:00:01.0: enabling device (0000 -> 0003)
vm-test-run-horae-e2e-oidc> server # [    3.782954] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)
vm-test-run-horae-e2e-oidc> server # [    3.802689] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)
vm-test-run-horae-e2e-oidc> server # [    3.808530] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)
vm-test-run-horae-e2e-oidc> server # [    3.821358] virtio-pci 0000:00:05.0: enabling device (0000 -> 0003)
vm-test-run-horae-e2e-oidc> server # [    3.833042] virtio-pci 0000:00:06.0: enabling device (0000 -> 0003)
vm-test-run-horae-e2e-oidc> server # [    3.838213] virtio-pci 0000:00:07.0: enabling device (0000 -> 0003)
vm-test-run-horae-e2e-oidc> server # [    3.850497] virtio-pci 0000:00:08.0: enabling device (0000 -> 0002)
vm-test-run-horae-e2e-oidc> server # [    3.855114] virtio-pci 0000:00:09.0: enabling device (0000 -> 0002)
vm-test-run-horae-e2e-oidc> server # [    3.866895] virtio-pci 0000:00:0b.0: enabling device (0000 -> 0003)
vm-test-run-horae-e2e-oidc> server # [    3.872293] virtio-pci 0000:00:0c.0: enabling device (0000 -> 0003)
vm-test-run-horae-e2e-oidc> server # [    3.982622] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
vm-test-run-horae-e2e-oidc> server # [    4.046287] msm_serial: driver initialized
vm-test-run-horae-e2e-oidc> server # [    4.050242] SuperH (H)SCI(F) driver initialized
vm-test-run-horae-e2e-oidc> server # [    4.060112] STM32 USART driver initialized
vm-test-run-horae-e2e-oidc> server # [    4.336953] loop: module loaded
vm-test-run-horae-e2e-oidc> server # [    4.338263] virtio_blk virtio4: 1/0/0 default/read/poll queues
vm-test-run-horae-e2e-oidc> server # [    4.354638] virtio_blk virtio4: [vda] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB)
vm-test-run-horae-e2e-oidc> server # [    4.425278] virtio_blk virtio5: 1/0/0 default/read/poll queues
vm-test-run-horae-e2e-oidc> server # [    4.437903] virtio_blk virtio5: [vdb] 3105224 512-byte logical blocks (1.59 GB/1.48 GiB)
vm-test-run-horae-e2e-oidc> server # [    4.473002] megasas: 07.734.00.00-rc1
vm-test-run-horae-e2e-oidc> server # [    4.497564] physmap-flash 0.flash: physmap platform flash device: [mem 0x00000000-0x03ffffff]
vm-test-run-horae-e2e-oidc> server # [    4.517718] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000
vm-test-run-horae-e2e-oidc> server # [    4.519150] Intel/Sharp Extended Query Table at 0x0031
vm-test-run-horae-e2e-oidc> server # [    4.524905] Using buffer write method
vm-test-run-horae-e2e-oidc> server # [    4.526526] physmap-flash 0.flash: physmap platform flash device: [mem 0x04000000-0x07ffffff]
vm-test-run-horae-e2e-oidc> server # [    4.538032] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000
vm-test-run-horae-e2e-oidc> server # [    4.538584] Intel/Sharp Extended Query Table at 0x0031
vm-test-run-horae-e2e-oidc> server # [    4.554393] Using buffer write method
vm-test-run-horae-e2e-oidc> server # [    4.555115] Concatenating MTD devices:
vm-test-run-horae-e2e-oidc> server # [    4.555268] (0): "0.flash"
vm-test-run-horae-e2e-oidc> server # [    4.557621] (1): "0.flash"
vm-test-run-horae-e2e-oidc> server # [    4.557941] into device "0.flash"
vm-test-run-horae-e2e-oidc> server # [    6.137376] Freeing initrd memory: 25716K
vm-test-run-horae-e2e-oidc> server # [    6.410377] tun: Universal TUN/TAP device driver, 1.6
vm-test-run-horae-e2e-oidc> server # [    6.445889] thunder_xcv, ver 1.0
vm-test-run-horae-e2e-oidc> server # [    6.446703] thunder_bgx, ver 1.0
vm-test-run-horae-e2e-oidc> server # [    6.447272] nicpf, ver 1.0
vm-test-run-horae-e2e-oidc> server # [    6.459701] e1000: Intel(R) PRO/1000 Network Driver
vm-test-run-horae-e2e-oidc> server # [    6.460150] e1000: Copyright (c) 1999-2006 Intel Corporation.
vm-test-run-horae-e2e-oidc> server # [    6.460789] e1000e: Intel(R) PRO/1000 Network Driver
vm-test-run-horae-e2e-oidc> server # [    6.460935] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
vm-test-run-horae-e2e-oidc> server # [    6.461504] igb: Intel(R) Gigabit Ethernet Network Driver
vm-test-run-horae-e2e-oidc> server # [    6.461651] igb: Copyright (c) 2007-2014 Intel Corporation.
vm-test-run-horae-e2e-oidc> server # [    6.462254] igbvf: Intel(R) Gigabit Virtual Function Network Driver
vm-test-run-horae-e2e-oidc> server # [    6.462489] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.
vm-test-run-horae-e2e-oidc> server # [    6.468911] sky2: driver version 1.30
vm-test-run-horae-e2e-oidc> server # [    6.495328] ehci-pci 0000:00:0a.0: EHCI Host Controller
vm-test-run-horae-e2e-oidc> server # [    6.497155] ehci-pci 0000:00:0a.0: new USB bus registered, assigned bus number 1
vm-test-run-horae-e2e-oidc> server # [    6.503596] ehci-pci 0000:00:0a.0: irq 15, io mem 0x10089000
vm-test-run-horae-e2e-oidc> server # [    6.512928] usbcore: registered new interface driver usb-storage
vm-test-run-horae-e2e-oidc> server # [    6.514196] usbcore: registered new interface driver usbserial_generic
vm-test-run-horae-e2e-oidc> server # [    6.517063] ehci-pci 0000:00:0a.0: USB 2.0 started, EHCI 1.00
vm-test-run-horae-e2e-oidc> server # [    6.526610] usbserial: USB Serial support registered for generic
vm-test-run-horae-e2e-oidc> server # [    6.550924] hv_vmbus: registering driver hyperv_keyboard
vm-test-run-horae-e2e-oidc> server # [    6.553117] hub 1-0:1.0: USB hub found
vm-test-run-horae-e2e-oidc> server # [    6.560532] hub 1-0:1.0: 6 ports detected
vm-test-run-horae-e2e-oidc> server # [    6.588330] rtc-pl031 9010000.pl031: registered as rtc0
vm-test-run-horae-e2e-oidc> server # [    6.589813] rtc-pl031 9010000.pl031: setting system clock to 2026-11-03T11:11:21 UTC (1793704281)
vm-test-run-horae-e2e-oidc> server # [    6.598480] i2c_dev: i2c /dev entries driver
vm-test-run-horae-e2e-oidc> server # [    6.645548] sdhci: Secure Digital Host Controller Interface driver
vm-test-run-horae-e2e-oidc> server # [    6.645868] sdhci: Copyright(c) Pierre Ossman
vm-test-run-horae-e2e-oidc> server # [    6.652007] Synopsys Designware Multimedia Card Interface Driver
vm-test-run-horae-e2e-oidc> server # [    6.659247] sdhci-pltfm: SDHCI platform and OF driver helper
vm-test-run-horae-e2e-oidc> server # [    6.685429] hid: raw HID events driver (C) Jiri Kosina
vm-test-run-horae-e2e-oidc> server # [    6.692416] usbcore: registered new interface driver usbhid
vm-test-run-horae-e2e-oidc> server # [    6.692723] usbhid: USB HID core driver
vm-test-run-horae-e2e-oidc> server # [    6.723187] hw perfevents: enabled with armv8_pmuv3 PMU driver, 7 (0,8000003f) counters available
vm-test-run-horae-e2e-oidc> server # [    6.753509] drop_monitor: Initializing network drop monitor service
vm-test-run-horae-e2e-oidc> server # [    6.757663] NET: Registered PF_INET6 protocol family
vm-test-run-horae-e2e-oidc> server # [    6.780379] Segment Routing with IPv6
vm-test-run-horae-e2e-oidc> server # [    6.781238] In-situ OAM (IOAM) with IPv6
vm-test-run-horae-e2e-oidc> server # [    6.782722] NET: Registered PF_PACKET protocol family
vm-test-run-horae-e2e-oidc> server # [    6.786448] 9pnet: Installing 9P2000 support
vm-test-run-horae-e2e-oidc> server # [    6.795681] Key type dns_resolver registered
vm-test-run-horae-e2e-oidc> server # [    6.834157] usb 1-1: new high-speed USB device number 2 using ehci-pci
vm-test-run-horae-e2e-oidc> server # [    6.922800] registered taskstats version 1
vm-test-run-horae-e2e-oidc> server # [    6.930643] Loading compiled-in X.509 certificates
vm-test-run-horae-e2e-oidc> server # [    7.073931] input: QEMU QEMU USB Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:0a.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input0
vm-test-run-horae-e2e-oidc> server # [    7.140941] Demotion targets for Node 0: null
vm-test-run-horae-e2e-oidc> server # [    7.156807] Key type .fscrypt registered
vm-test-run-horae-e2e-oidc> server # [    7.157174] Key type fscrypt-provisioning registered
vm-test-run-horae-e2e-oidc> server # [    7.161418] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:0a.0-1/input0
vm-test-run-horae-e2e-oidc> server # [    7.169650] ima: No TPM chip found, activating TPM-bypass!
vm-test-run-horae-e2e-oidc> server # [    7.170062] ima: Allocated hash algorithm: sha1
vm-test-run-horae-e2e-oidc> server # [    7.176037] ima: No architecture policies found
vm-test-run-horae-e2e-oidc> server # [    7.195142] input: gpio-keys as /devices/platform/gpio-keys/input/input1
vm-test-run-horae-e2e-oidc> server # [    7.299742] usb 1-2: new high-speed USB device number 3 using ehci-pci
vm-test-run-horae-e2e-oidc> server # [    7.321113] clk: Disabling unused clocks
vm-test-run-horae-e2e-oidc> server # [    7.322204] PM: genpd: Disabling unused power domains
vm-test-run-horae-e2e-oidc> server # [    7.588138] input: QEMU QEMU USB Tablet as /devices/platform/4010000000.pcie/pci0000:00/0000:00:0a.0/usb1/1-2/1-2:1.0/0003:0627:0001.0002/input/input2
vm-test-run-horae-e2e-oidc> server # [    7.591694] hid-generic 0003:0627:0001.0002: input,hidraw1: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:0a.0-2/input0
vm-test-run-horae-e2e-oidc> server # [    8.009662] Freeing unused kernel memory: 4736K
vm-test-run-horae-e2e-oidc> server # [    8.012838] Run /init as init process
vm-test-run-horae-e2e-oidc> server # [    8.343403] systemd[1]: Successfully made /usr/ read-only.
vm-test-run-horae-e2e-oidc> server # [    8.718632] systemd[1]: systemd 260.2 running in system mode (+PAM +AUDIT -SELINUX +APPARMOR +IMA +IPE +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -BTF -XKBCOMMON +UTMP +LIBARCHIVE)
vm-test-run-horae-e2e-oidc> server # [    8.723960] systemd[1]: Detected virtualization qemu.
vm-test-run-horae-e2e-oidc> server # [    8.726108] systemd[1]: Detected architecture arm64.
vm-test-run-horae-e2e-oidc> server # [    8.727741] systemd[1]: Running in initrd.
vm-test-run-horae-e2e-oidc> server # [    8.747570] systemd[1]: Initializing machine ID from random generator.
vm-test-run-horae-e2e-oidc> server # [    8.758406] systemd[1]: Hostname set to <server>.
vm-test-run-horae-e2e-oidc> server # [   10.886292] systemd[1]: Queued start job for default target Initrd Default Target.
vm-test-run-horae-e2e-oidc> server # [   10.991274] systemd[1]: Created slice Slice /system/modprobe.
vm-test-run-horae-e2e-oidc> server # [   11.002881] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
vm-test-run-horae-e2e-oidc> server # [   11.007130] systemd[1]: Expecting device /dev/disk/by-label/nix-store...
vm-test-run-horae-e2e-oidc> server # [   11.009986] systemd[1]: Expecting device /dev/disk/by-label/nixos...
vm-test-run-horae-e2e-oidc> server # [   11.012683] systemd[1]: Reached target Path Units.
vm-test-run-horae-e2e-oidc> server # [   11.014490] systemd[1]: Reached target Slice Units.
vm-test-run-horae-e2e-oidc> server # [   11.016603] systemd[1]: Reached target Swaps.
vm-test-run-horae-e2e-oidc> server # [   11.018443] systemd[1]: Reached target Timer Units.
vm-test-run-horae-e2e-oidc> server # [   11.027887] systemd[1]: Listening on D-Bus System Message Bus Socket.
vm-test-run-horae-e2e-oidc> server # [   11.035003] systemd[1]: Listening on Journal Socket (/dev/log).
vm-test-run-horae-e2e-oidc> server # [   11.041188] systemd[1]: Listening on Journal Sockets.
vm-test-run-horae-e2e-oidc> server # [   11.046366] systemd[1]: Listening on udev Control Socket.
vm-test-run-horae-e2e-oidc> server # [   11.050896] systemd[1]: Listening on udev Kernel Socket.
vm-test-run-horae-e2e-oidc> server # [   11.053343] systemd[1]: Reached target Socket Units.
vm-test-run-horae-e2e-oidc> server # [   11.118922] systemd[1]: Starting Create List of Static Device Nodes...
vm-test-run-horae-e2e-oidc> server # [   11.189839] systemd[1]: Starting Load Kernel Module 9pnet_virtio...
vm-test-run-horae-e2e-oidc> server # [   11.193929] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs
vm-test-run-horae-e2e-oidc> server # [   11.305723] systemd[1]: Mounting Kernel Configuration File System...
vm-test-run-horae-e2e-oidc> server # [   11.730326] systemd[1]: Starting Journal Service...
vm-test-run-horae-e2e-oidc> server # [   11.865725] systemd[1]: Starting Load Kernel Modules...
vm-test-run-horae-e2e-oidc> server # [   11.873462] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki
vm-test-run-horae-e2e-oidc> server # [   11.989578] systemd[1]: Starting Coldplug All udev Devices...
vm-test-run-horae-e2e-oidc> server # [   12.290358] systemd[1]: Finished Create List of Static Device Nodes.
vm-test-run-horae-e2e-oidc> server # [   12.564461] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   12.607058] systemd[1]: Finished Load Kernel Module 9pnet_virtio.
vm-test-run-horae-e2e-oidc> server # [   12.673870] systemd[1]: Mounted Kernel Configuration File System.
vm-test-run-horae-e2e-oidc> server # [   12.845691] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...
vm-test-run-horae-e2e-oidc> server # [   13.361631] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log.
vm-test-run-horae-e2e-oidc> server # [   13.393564] device-mapper: ioctl: 4.50.0-ioctl (2025-04-28) initialised: dm-devel@lists.linux.dev
vm-test-run-horae-e2e-oidc> server # [   13.677436] [drm] pci: virtio-gpu-pci detected at 0000:00:08.0
vm-test-run-horae-e2e-oidc> server # [   13.678876] [drm] features: -virgl +edid -resource_blob -host_visible
vm-test-run-horae-e2e-oidc> server # [   13.679001] [drm] features: -context_init
vm-test-run-horae-e2e-oidc> server # [   13.708721] [drm] number of scanouts: 1
vm-test-run-horae-e2e-oidc> server # [   13.709070] [drm] number of cap sets: 0
vm-test-run-horae-e2e-oidc> server # [   13.795736] virtio-pci 0000:00:08.0: [drm] Registered 1 planes with drm panic
vm-test-run-horae-e2e-oidc> server # [   13.796156] [drm] Initialized virtio_gpu 0.1.0 for 0000:00:08.0 on minor 0
vm-test-run-horae-e2e-oidc> server # [   13.950998] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.
vm-test-run-horae-e2e-oidc> server # [   13.974087] systemd-journald[74]: Collecting audit messages is disabled.
vm-test-run-horae-e2e-oidc> server # [   14.109682] systemd[1]: Starting Create Static Device Nodes in /dev...
vm-test-run-horae-e2e-oidc> server # [   14.206318] Console: switching to colour frame buffer device 160x50
vm-test-run-horae-e2e-oidc> server # [   14.272203] virtio-pci 0000:00:08.0: [drm] fb0: virtio_gpudrmfb frame buffer device
vm-test-run-horae-e2e-oidc> server # [   14.425683] systemd[1]: Finished Load Kernel Modules.
vm-test-run-horae-e2e-oidc> server # [   14.609948] systemd[1]: Starting Apply Kernel Variables...
vm-test-run-horae-e2e-oidc> server # [   15.271008] systemd[1]: Finished Create Static Device Nodes in /dev.
vm-test-run-horae-e2e-oidc> server # [   15.318019] systemd[1]: Reached target Preparation for Local File Systems.
vm-test-run-horae-e2e-oidc> server # [   15.329290] systemd[1]: Reached target Local File Systems.
vm-test-run-horae-e2e-oidc> server # [   15.490168] systemd[1]: Starting Rule-based Manager for Device Events and Files...
vm-test-run-horae-e2e-oidc> server # [   15.787058] systemd[1]: Finished Apply Kernel Variables.
vm-test-run-horae-e2e-oidc> server # [   19.698558] systemd[1]: Started Rule-based Manager for Device Events and Files.
vm-test-run-horae-e2e-oidc> server # [   20.161727] systemd[1]: Started Journal Service.
vm-test-run-horae-e2e-oidc> server # [   20.054283] systemd-modules-load[75]: Inserted module 'dm_mod'
vm-test-run-horae-e2e-oidc> server # [   20.149429] systemd-modules-load[75]: Module 'virtio_balloon' is built in
vm-test-run-horae-e2e-oidc> server # [   20.175574] systemd-modules-load[75]: Module 'virtio_console' is built in
vm-test-run-horae-e2e-oidc> server # [   20.215499] systemd-modules-load[75]: Inserted module 'virtio_gpu'
vm-test-run-horae-e2e-oidc> server # [   20.264931] systemd-modules-load[75]: Module 'virtio_rng' is built in
vm-test-run-horae-e2e-oidc> server # [   20.327830] systemd-udevd[81]: Using default interface naming scheme 'v260'.
vm-test-run-horae-e2e-oidc> server # [   20.399938] systemd[1]: Starting Create System Files and Directories...
vm-test-run-horae-e2e-oidc> server # [   21.539445] systemd[1]: Finished Create System Files and Directories.
vm-test-run-horae-e2e-oidc> server # [   22.273717] systemd[1]: Starting Virtual Console Setup...
vm-test-run-horae-e2e-oidc> server # [   23.714493] systemd-vconsole-setup[103]: Configuration of first virtual console was skipped, ignoring remaining ones.
vm-test-run-horae-e2e-oidc> server # [   23.779634] systemd[1]: Finished Virtual Console Setup.
vm-test-run-horae-e2e-oidc> server # [   46.724175] systemd[1]: Finished Coldplug All udev Devices.
vm-test-run-horae-e2e-oidc> server # [   46.757635] systemd[1]: Reached target System Initialization.
vm-test-run-horae-e2e-oidc> server # [   46.761941] systemd[1]: Reached target Basic System.
vm-test-run-horae-e2e-oidc> server # [   55.881066] (udev-worker)[110]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.
vm-test-run-horae-e2e-oidc> server # [   55.902903] (udev-worker)[110]: Network interface NamePolicy= disabled on kernel command line.
vm-test-run-horae-e2e-oidc> server # [   55.930439] (udev-worker)[107]: Network interface NamePolicy= disabled on kernel command line.
vm-test-run-horae-e2e-oidc> server # [   56.577975] systemd[1]: Found device /dev/disk/by-label/nix-store.
vm-test-run-horae-e2e-oidc> server # [   56.929993] systemd[1]: Found device /dev/disk/by-label/nixos.
vm-test-run-horae-e2e-oidc> server # [   56.997279] systemd[1]: Reached target Initrd Root Device.
vm-test-run-horae-e2e-oidc> server # [   57.069027] systemd[1]: Starting File System Check on /dev/disk/by-label/nixos...
vm-test-run-horae-e2e-oidc> server # [   58.382879] systemd-fsck[121]: nixos: clean, 12/65536 files, 13019/262144 blocks
vm-test-run-horae-e2e-oidc> server # [   58.550894] systemd[1]: Finished File System Check on /dev/disk/by-label/nixos.
vm-test-run-horae-e2e-oidc> server # [   58.635870] systemd[1]: Mounting /sysroot...
vm-test-run-horae-e2e-oidc> server # [   59.430293] EXT4-fs (vda): mounted filesystem 2241a54f-b3d1-4ee5-bb43-d0b4c5a958d0 r/w with ordered data mode. Quota mode: none.
vm-test-run-horae-e2e-oidc> server # [   59.453569] systemd[1]: Mounted /sysroot.
vm-test-run-horae-e2e-oidc> server # [   59.513220] systemd[1]: Reached target Initrd Root File System.
vm-test-run-horae-e2e-oidc> server # [   59.707766] systemd[1]: Mounting /sysroot/nix/.ro-store...
vm-test-run-horae-e2e-oidc> server # [   59.829777] systemd[1]: Mounting /sysroot/nix/.rw-store...
vm-test-run-horae-e2e-oidc> server # [   60.067967] systemd[1]: Mounting /sysroot/run...
vm-test-run-horae-e2e-oidc> server # [   60.390269] systemd[1]: Mounting /sysroot/tmp/shared...
vm-test-run-horae-e2e-oidc> server # [   60.743486] systemd[1]: Mounting /sysroot/tmp/xchg...
vm-test-run-horae-e2e-oidc> server # [   61.089962] systemd[1]: Starting Mountpoints Configured in the Real Root...
vm-test-run-horae-e2e-oidc> server # [   62.060497] erofs (device vdb): mounted with root inode @ nid 36.
vm-test-run-horae-e2e-oidc> server # [   62.939375] systemd-sysroot-fstab-check[134]: /sysroot should be mounted in the initrd, will request daemon-reload.
vm-test-run-horae-e2e-oidc> server # [   63.299752] systemd[1]: Mounted /sysroot/nix/.ro-store.
vm-test-run-horae-e2e-oidc> server # [   63.321606] systemd[1]: Mounted /sysroot/nix/.rw-store.
vm-test-run-horae-e2e-oidc> server # [   63.331183] systemd[1]: Mounted /sysroot/run.
vm-test-run-horae-e2e-oidc> server # [   63.362093] systemd[1]: Mounted /sysroot/tmp/shared.
vm-test-run-horae-e2e-oidc> server # [   63.378822] systemd[1]: Mounted /sysroot/tmp/xchg.
vm-test-run-horae-e2e-oidc> server # [   63.805518] systemd[1]: Reload requested from client PID 134 ('systemd-sysroot') (unit initrd-parse-etc.service)...
vm-test-run-horae-e2e-oidc> server # [   63.821180] systemd[1]: Reloading...
vm-test-run-horae-e2e-oidc> server # [   72.347133] systemd[1]: Reloading finished in 8476 ms.
vm-test-run-horae-e2e-oidc> server # [   72.843289] systemd-sysroot-fstab-check[134]: Requesting initrd-fs.target/start/replace...
vm-test-run-horae-e2e-oidc> server # [   72.982614] systemd-sysroot-fstab-check[134]: Requesting swap.target/start/replace...
vm-test-run-horae-e2e-oidc> server # [   73.083577] systemd[1]: initrd-parse-etc.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   73.117352] systemd[1]: Finished Mountpoints Configured in the Real Root.
vm-test-run-horae-e2e-oidc> server # [   73.126224] systemd[1]: initrd-parse-etc.service: Triggering OnSuccess= dependencies.
vm-test-run-horae-e2e-oidc> server # [   73.437887] systemd[1]: Starting rw-sysroot-nix-store.service...
vm-test-run-horae-e2e-oidc> server # [   73.890430] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   73.917224] systemd[1]: Finished rw-sysroot-nix-store.service.
vm-test-run-horae-e2e-oidc> server # [   74.027617] systemd[1]: Mounting /sysroot/nix/store...
vm-test-run-horae-e2e-oidc> server # [   74.940994] systemd[1]: Mounted /sysroot/nix/store.
vm-test-run-horae-e2e-oidc> server # [   74.969719] systemd[1]: Reached target Initrd File Systems.
vm-test-run-horae-e2e-oidc> server # [   75.035388] systemd[1]: Starting Find NixOS closure...
vm-test-run-horae-e2e-oidc> server # [   75.181091] systemd[1]: Starting Create Volatile Files and Directories in the Real Root...
vm-test-run-horae-e2e-oidc> server # [   76.151990] systemd[1]: Finished Create Volatile Files and Directories in the Real Root.
vm-test-run-horae-e2e-oidc> server # [   76.254584] systemd[1]: sysroot-run-credentials-systemd\x2dtmpfiles\x2dsetup\x2dsysroot.service.mount: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   76.782841] systemd[1]: Finished Find NixOS closure.
vm-test-run-horae-e2e-oidc> server # [   76.817854] systemd[1]: Reached target Initrd Default Target.
vm-test-run-horae-e2e-oidc> server # [   76.897595] systemd[1]: Starting Cleaning Up and Shutting Down Daemons...
vm-test-run-horae-e2e-oidc> server # [   77.943413] systemd[1]: initrd-cleanup.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   77.962385] systemd[1]: Finished Cleaning Up and Shutting Down Daemons.
vm-test-run-horae-e2e-oidc> server # [   78.010985] systemd[1]: Stopped target Initrd Default Target.
vm-test-run-horae-e2e-oidc> server # [   78.018372] systemd[1]: Stopped target Basic System.
vm-test-run-horae-e2e-oidc> server # [   78.033759] systemd[1]: Stopped target Initrd Root Device.
vm-test-run-horae-e2e-oidc> server # [   78.043902] systemd[1]: Stopped target Path Units.
vm-test-run-horae-e2e-oidc> server # [   78.059360] systemd[1]: systemd-ask-password-console.path: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   78.072001] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.
vm-test-run-horae-e2e-oidc> server # [   78.085954] systemd[1]: Stopped target Slice Units.
vm-test-run-horae-e2e-oidc> server # [   78.098254] systemd[1]: Stopped target Socket Units.
vm-test-run-horae-e2e-oidc> server # [   78.110426] systemd[1]: Stopped target System Initialization.
vm-test-run-horae-e2e-oidc> server # [   78.118343] systemd[1]: Stopped target Swaps.
vm-test-run-horae-e2e-oidc> server # [   78.130057] systemd[1]: Stopped target Timer Units.
vm-test-run-horae-e2e-oidc> server # [   78.142907] systemd[1]: dbus.socket: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   78.153964] systemd[1]: Closed D-Bus System Message Bus Socket.
vm-test-run-horae-e2e-oidc> server # [   78.166362] systemd[1]: initrd-find-nixos-closure.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   78.174601] systemd[1]: Stopped Find NixOS closure.
vm-test-run-horae-e2e-oidc> server # [   78.233336] systemd[1]: Starting Load Kernel Module 9pnet_virtio...
vm-test-run-horae-e2e-oidc> server # [   78.354865] systemd[1]: Starting rw-sysroot-nix-store.service...
vm-test-run-horae-e2e-oidc> server # [   78.374627] systemd[1]: systemd-sysctl.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   78.389394] systemd[1]: Stopped Apply Kernel Variables.
vm-test-run-horae-e2e-oidc> server # [   78.407911] systemd[1]: systemd-modules-load.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   78.433727] systemd[1]: Stopped Load Kernel Modules.
vm-test-run-horae-e2e-oidc> server # [   78.446323] systemd[1]: systemd-tmpfiles-setup-sysroot.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   78.474290] systemd[1]: Stopped Create Volatile Files and Directories in the Real Root.
vm-test-run-horae-e2e-oidc> server # [   78.493174] systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   78.509336] systemd[1]: Stopped Create System Files and Directories.
vm-test-run-horae-e2e-oidc> server # [   78.538606] systemd[1]: Stopped target Local File Systems.
vm-test-run-horae-e2e-oidc> server # [   78.556941] systemd[1]: Stopped target Preparation for Local File Systems.
vm-test-run-horae-e2e-oidc> server # [   78.577392] systemd[1]: systemd-udev-trigger.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   78.589979] systemd[1]: Stopped Coldplug All udev Devices.
vm-test-run-horae-e2e-oidc> server # [   78.598065] systemd[1]: systemd-udev-trigger.service: Consumed 18.216s CPU time over 1min 6.747s wall clock time, 9.3M memory peak.
vm-test-run-horae-e2e-oidc> server # [   78.621379] systemd[1]: Stopping Rule-based Manager for Device Events and Files...
vm-test-run-horae-e2e-oidc> server # [   78.646372] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   78.657987] systemd[1]: Stopped Virtual Console Setup.
vm-test-run-horae-e2e-oidc> server # [   79.262612] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   79.289490] systemd[1]: Finished Load Kernel Module 9pnet_virtio.
vm-test-run-horae-e2e-oidc> server # [   79.321625] systemd[1]: rw-sysroot-nix-store.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   79.351334] systemd[1]: Finished rw-sysroot-nix-store.service.
vm-test-run-horae-e2e-oidc> server # [   80.119417] systemd[1]: systemd-udevd.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   80.138502] systemd[1]: Stopped Rule-based Manager for Device Events and Files.
vm-test-run-horae-e2e-oidc> server # [   80.149394] systemd[1]: systemd-udevd.service: Consumed 23.688s CPU time over 1min 4.788s wall clock time, 16.2M memory peak.
vm-test-run-horae-e2e-oidc> server # [   80.163500] systemd[1]: systemd-udevd-control.socket: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   80.171941] systemd[1]: Closed udev Control Socket.
vm-test-run-horae-e2e-oidc> server # [   80.211387] systemd[1]: Starting Cleanup udev Database...
vm-test-run-horae-e2e-oidc> server # [   80.221297] systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   80.230344] systemd[1]: Stopped Create Static Device Nodes in /dev.
vm-test-run-horae-e2e-oidc> server # [   80.253875] systemd[1]: systemd-tmpfiles-setup-dev-early.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   80.262011] systemd[1]: Stopped Create Static Device Nodes in /dev gracefully.
vm-test-run-horae-e2e-oidc> server # [   80.266365] systemd[1]: kmod-static-nodes.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   80.274241] systemd[1]: Stopped Create List of Static Device Nodes.
vm-test-run-horae-e2e-oidc> server # [   80.777358] systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   80.794969] systemd[1]: Finished Cleanup udev Database.
vm-test-run-horae-e2e-oidc> server # [   80.815962] systemd[1]: Reached target Switch Root.
vm-test-run-horae-e2e-oidc> server # [   80.860704] systemd[1]: Starting NixOS Activation...
vm-test-run-horae-e2e-oidc> server # [   82.521796] initrd-nixos-activation-start[180]: booting system configuration /nix/store/whgc6x44bw1l966rzs1hldz2nmxhk2hd-nixos-system-server-test
vm-test-run-horae-e2e-oidc> server # [   83.158617] initrd-nixos-activation-start[180]: running activation script...
vm-test-run-horae-e2e-oidc> server # [   88.578125] initrd-nixos-activation-start[203]: setting up /etc...
vm-test-run-horae-e2e-oidc> server # [   91.227617] systemd[1]: initrd-nixos-activation.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [   91.238476] systemd[1]: Finished NixOS Activation.
vm-test-run-horae-e2e-oidc> server # [   91.249685] systemd[1]: initrd-nixos-activation.service: Consumed 8.283s CPU time over 10.363s wall clock time, 36.6M memory peak.
vm-test-run-horae-e2e-oidc> server # [   91.290704] systemd[1]: Starting Switch Root...
vm-test-run-horae-e2e-oidc> server # [   91.606839] systemd[1]: Switching root.
vm-test-run-horae-e2e-oidc> server # [   92.077909] systemd-journald[74]: Received SIGTERM from PID 1 (systemd).
vm-test-run-horae-e2e-oidc> server # [   94.280366] systemd[1]: systemd 260.2 running in system mode (+PAM +AUDIT -SELINUX +APPARMOR +IMA +IPE +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -BTF -XKBCOMMON +UTMP +LIBARCHIVE)
vm-test-run-horae-e2e-oidc> server # [   94.287726] systemd[1]: Detected virtualization qemu.
vm-test-run-horae-e2e-oidc> server # [   94.292081] systemd[1]: Detected architecture arm64.
vm-test-run-horae-e2e-oidc> server # [   94.298153] systemd[1]: Detected first boot.
vm-test-run-horae-e2e-oidc> server # [   94.328409] systemd[1]: Initializing machine ID from random generator.
vm-test-run-horae-e2e-oidc> server # [   97.688833] systemd[1]: bpf-restrict-fs: LSM BPF program attached
vm-test-run-horae-e2e-oidc> server # [   99.906413] systemd[1]: Applying preset policy.
vm-test-run-horae-e2e-oidc> server # [  105.142896] systemd[1]: Populated /etc with preset unit settings.
vm-test-run-horae-e2e-oidc> server # [  110.109959] systemd[1]: initrd-switch-root.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [  110.121805] systemd[1]: Stopped initrd-switch-root.service.
vm-test-run-horae-e2e-oidc> server # [  110.197432] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.
vm-test-run-horae-e2e-oidc> server # [  110.243183] systemd[1]: Created slice Slice /system/getty.
vm-test-run-horae-e2e-oidc> server # [  110.275233] systemd[1]: Created slice User and Session Slice.
vm-test-run-horae-e2e-oidc> server # [  110.290183] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
vm-test-run-horae-e2e-oidc> server # [  110.302945] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
vm-test-run-horae-e2e-oidc> server # [  110.313951] systemd[1]: Expecting device /dev/hvc0...
vm-test-run-horae-e2e-oidc> server # [  110.322790] systemd[1]: Expecting device /dev/ttyAMA0...
vm-test-run-horae-e2e-oidc> server # [  110.331066] systemd[1]: Reached target Local Encrypted Volumes.
vm-test-run-horae-e2e-oidc> server # [  110.340986] systemd[1]: Stopped target initrd-fs.target.
vm-test-run-horae-e2e-oidc> server # [  110.350600] systemd[1]: Stopped target initrd-root-fs.target.
vm-test-run-horae-e2e-oidc> server # [  110.359070] systemd[1]: Stopped target initrd-switch-root.target.
vm-test-run-horae-e2e-oidc> server # [  110.367890] systemd[1]: Reached target Virtual Machines and Containers.
vm-test-run-horae-e2e-oidc> server # [  110.377069] systemd[1]: Reached target Path Units.
vm-test-run-horae-e2e-oidc> server # [  110.385103] systemd[1]: Reached target Remote File Systems.
vm-test-run-horae-e2e-oidc> server # [  110.396178] systemd[1]: Reached target Slice Units.
vm-test-run-horae-e2e-oidc> server # [  110.405170] systemd[1]: Reached target Swaps.
vm-test-run-horae-e2e-oidc> server # [  110.451029] systemd[1]: Listening on Query the User Interactively for a Password.
vm-test-run-horae-e2e-oidc> server # [  110.494784] systemd[1]: Listening on Process Core Dump Socket.
vm-test-run-horae-e2e-oidc> server # [  110.530352] systemd[1]: Listening on Credential Encryption/Decryption.
vm-test-run-horae-e2e-oidc> server # [  110.570110] systemd[1]: Listening on Factory Reset Management.
vm-test-run-horae-e2e-oidc> server # [  110.645046] systemd[1]: Starting Journal Log Access Socket...
vm-test-run-horae-e2e-oidc> server # [  110.688484] systemd[1]: Listening on Journal Audit Socket.
vm-test-run-horae-e2e-oidc> server # [  110.739106] systemd[1]: Listening on Console Output Muting Service Socket.
vm-test-run-horae-e2e-oidc> server # [  110.754189] systemd[1]: Listening on Userspace Out-Of-Memory (OOM) Killer Socket.
vm-test-run-horae-e2e-oidc> server # [  110.764866] systemd[1]: TPM PCR Measurements skipped, unmet condition check ConditionSecurity=measured-uki
vm-test-run-horae-e2e-oidc> server # [  110.773966] systemd[1]: Make TPM PCR Policy skipped, unmet condition check ConditionSecurity=measured-uki
vm-test-run-horae-e2e-oidc> server # [  110.850965] systemd[1]: Listening on Disk Repartitioning Service Socket.
vm-test-run-horae-e2e-oidc> server # [  110.862718] systemd[1]: Listening on udev Control Socket.
vm-test-run-horae-e2e-oidc> server # [  110.875736] systemd[1]: Listening on udev Varlink Socket.
vm-test-run-horae-e2e-oidc> server # [  110.950506] systemd[1]: Mounting Huge Pages File System...
vm-test-run-horae-e2e-oidc> server # [  111.057740] systemd[1]: Mounting POSIX Message Queue File System...
vm-test-run-horae-e2e-oidc> server # [  111.205555] systemd[1]: Mounting Kernel Debug File System...
vm-test-run-horae-e2e-oidc> server # [  111.409754] systemd[1]: Mounting Kernel Trace File System...
vm-test-run-horae-e2e-oidc> server # [  111.798350] systemd[1]: Starting Create List of Static Device Nodes...
vm-test-run-horae-e2e-oidc> server # [  112.137966] systemd[1]: Starting Load Kernel Module 9pnet_virtio...
vm-test-run-horae-e2e-oidc> server # [  112.179839] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs
vm-test-run-horae-e2e-oidc> server # [  112.465438] systemd[1]: Mounting Kernel Configuration File System...
vm-test-run-horae-e2e-oidc> server # [  112.525659] systemd[1]: Load Kernel Module drm skipped, unmet condition check ConditionKernelModuleLoaded=!drm
vm-test-run-horae-e2e-oidc> server # [  112.585856] systemd[1]: Load Kernel Module efi_pstore skipped, unmet condition check ConditionKernelModuleLoaded=!efi_pstore
vm-test-run-horae-e2e-oidc> server # [  112.829570] systemd[1]: Starting Load Kernel Module fuse...
vm-test-run-horae-e2e-oidc> server # [  112.858212] systemd[1]: Clear Stale Hibernate Storage Info skipped, unmet condition check ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67
vm-test-run-horae-e2e-oidc> server # [  113.169569] systemd[1]: Starting Journal Service...
vm-test-run-horae-e2e-oidc> server # [  113.517863] systemd[1]: Starting Load Kernel Modules...
vm-test-run-horae-e2e-oidc> server # [  113.798467] fuse: init (API version 7.45)
vm-test-run-horae-e2e-oidc> server # [  113.922145] systemd[1]: Starting Userspace Out-Of-Memory (OOM) Killer...
vm-test-run-horae-e2e-oidc> server # [  114.158068] systemd[1]: Starting Remount Root and Kernel File Systems...
vm-test-run-horae-e2e-oidc> server # [  114.214896] systemd[1]: Early TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki
vm-test-run-horae-e2e-oidc> server # [  114.637789] systemd[1]: Starting Coldplug All udev Devices...
vm-test-run-horae-e2e-oidc> server # [  115.273690] systemd-journald[274]: Collecting audit messages is enabled.
vm-test-run-horae-e2e-oidc> server # [  115.486059] systemd[1]: Listening on Journal Log Access Socket.
vm-test-run-horae-e2e-oidc> server # [  115.550413] systemd[1]: Mounted Huge Pages File System.
vm-test-run-horae-e2e-oidc> server # [  115.606878] systemd[1]: Mounted POSIX Message Queue File System.
vm-test-run-horae-e2e-oidc> server # [  115.665838] systemd[1]: Mounted Kernel Debug File System.
vm-test-run-horae-e2e-oidc> server # [  115.722473] systemd[1]: Mounted Kernel Trace File System.
vm-test-run-horae-e2e-oidc> server # [  115.833342] systemd[1]: Finished Create List of Static Device Nodes.
vm-test-run-horae-e2e-oidc> server # [  115.915960] systemd[1]: modprobe@9pnet_virtio.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [  116.014424] systemd[1]: Finished Load Kernel Module 9pnet_virtio.
vm-test-run-horae-e2e-oidc> server # [  116.085464] systemd[1]: Mounted Kernel Configuration File System.
vm-test-run-horae-e2e-oidc> server # [  116.177676] systemd[1]: modprobe@fuse.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [  116.200675] EXT4-fs (vda): re-mounted 2241a54f-b3d1-4ee5-bb43-d0b4c5a958d0.
vm-test-run-horae-e2e-oidc> server # [  116.273225] systemd[1]: Finished Load Kernel Module fuse.
vm-test-run-horae-e2e-oidc> server # [  116.234400] systemd[1]: Queued start job for default target Multi-User System.
vm-test-run-horae-e2e-oidc> server # [  116.293074] systemd[1]: Unnecessary job was removed for /dev/vdb.
vm-test-run-horae-e2e-oidc> server # [  116.472333] systemd[1]: Started Journal Service.
vm-test-run-horae-e2e-oidc> server # [  116.359742] systemd[1]: systemd-journald.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [  116.399499] systemd[1]: systemd-journald.service: Consumed 2.910s CPU time over 1min 38.269s wall clock time, 4M memory peak.
vm-test-run-horae-e2e-oidc> server # [  116.455846] systemd-modules-load[275]: Module 'atkbd' is built in
vm-test-run-horae-e2e-oidc> server # [  116.495551] systemd-modules-load[275]: Module 'loop' is built in
vm-test-run-horae-e2e-oidc> server # [  116.541530] systemd[1]: Finished Load Kernel Modules.
vm-test-run-horae-e2e-oidc> server # [  116.575169] systemd[1]: Finished Remount Root and Kernel File Systems.
vm-test-run-horae-e2e-oidc> server # [  117.253426] systemd[1]: Listening on Disk Image Download Service Socket.
vm-test-run-horae-e2e-oidc> server # [  117.431956] systemd[1]: Mounting FUSE Control File System...
vm-test-run-horae-e2e-oidc> server # [  117.679305] systemd[1]: Starting Firewall...
vm-test-run-horae-e2e-oidc> server # [  117.997513] systemd[1]: Starting Flush Journal to Persistent Storage...
vm-test-run-horae-e2e-oidc> server # [  118.045541] systemd[1]: Platform Persistent Storage Archival skipped, unmet condition check ConditionDirectoryNotEmpty=/sys/fs/pstore
vm-test-run-horae-e2e-oidc> server # [  118.530915] systemd[1]: Starting Load/Save OS Random Seed...
vm-test-run-horae-e2e-oidc> server # [  118.593877] systemd-oomd[276]: No swap; memory pressure usage will be degraded
vm-test-run-horae-e2e-oidc> server # [  119.173269] systemd[1]: Starting Apply Kernel Variables...
vm-test-run-horae-e2e-oidc> server # [  119.826658] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...
vm-test-run-horae-e2e-oidc> server # [  119.846908] systemd[1]: TPM SRK Setup skipped, unmet condition check ConditionSecurity=measured-uki
vm-test-run-horae-e2e-oidc> server # [  120.346674] systemd-journald[274]: Received client request to flush runtime journal.
vm-test-run-horae-e2e-oidc> server # [  122.709952] systemd[1]: Started Userspace Out-Of-Memory (OOM) Killer.
vm-test-run-horae-e2e-oidc> server # [  122.790165] systemd[1]: Mounted FUSE Control File System.
vm-test-run-horae-e2e-oidc> server # [  122.886622] systemd[1]: Finished Load/Save OS Random Seed.
vm-test-run-horae-e2e-oidc> server # [  122.931243] systemd[1]: Reached target First Boot Complete.
vm-test-run-horae-e2e-oidc> server # [  122.983407] systemd[1]: Finished Flush Journal to Persistent Storage.
vm-test-run-horae-e2e-oidc> server # [  123.097515] systemd[1]: Finished Apply Kernel Variables.
vm-test-run-horae-e2e-oidc> server # [  123.867021] systemd[1]: Finished Create Static Device Nodes in /dev gracefully.
vm-test-run-horae-e2e-oidc> server # [  124.145424] systemd[1]: Starting Create Static Device Nodes in /dev...
vm-test-run-horae-e2e-oidc> server # [  125.707070] systemd[1]: Finished Create Static Device Nodes in /dev.
vm-test-run-horae-e2e-oidc> server # [  125.857399] systemd[1]: Reached target Preparation for Local File Systems.
vm-test-run-horae-e2e-oidc> server # [  125.989749] systemd[1]: Mounting /run/wrappers...
vm-test-run-horae-e2e-oidc> server # [  126.258045] systemd[1]: Starting Rule-based Manager for Device Events and Files...
vm-test-run-horae-e2e-oidc> server # [  127.530053] systemd[1]: Mounted /run/wrappers.
vm-test-run-horae-e2e-oidc> server # [  127.597319] systemd[1]: Reached target Local File Systems.
vm-test-run-horae-e2e-oidc> server # [  127.725304] systemd[1]: Listening on Boot Loader Control Service Socket.
vm-test-run-horae-e2e-oidc> server # [  127.895282] systemd[1]: Starting register-nix-paths.service...
vm-test-run-horae-e2e-oidc> server # [  128.205885] systemd[1]: Starting Create SUID/SGID Wrappers...
vm-test-run-horae-e2e-oidc> server # [  128.233322] systemd[1]: Update Boot Loader Random Seed skipped, no trigger condition checks were met.
vm-test-run-horae-e2e-oidc> server # [  128.719747] systemd[1]: Starting Save Transient machine-id to Disk...
vm-test-run-horae-e2e-oidc> server # [  129.293096] systemd[1]: Starting Create System Files and Directories...
vm-test-run-horae-e2e-oidc> server # [  132.009559] systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [  132.102332] systemd[1]: Finished Save Transient machine-id to Disk.
vm-test-run-horae-e2e-oidc> server # [  135.794508] systemd[1]: Finished Create System Files and Directories.
vm-test-run-horae-e2e-oidc> server # [  136.323288] systemd[1]: Starting Rebuild Journal Catalog...
vm-test-run-horae-e2e-oidc> server # [  136.846356] systemd[1]: Starting Record System Boot/Shutdown in UTMP...
vm-test-run-horae-e2e-oidc> server # [  139.838530] systemd[1]: Finished Record System Boot/Shutdown in UTMP.
vm-test-run-horae-e2e-oidc> server # [  143.198178] systemd[1]: Finished Rebuild Journal Catalog.
vm-test-run-horae-e2e-oidc> server # [  143.461911] systemd[1]: Starting Update is Completed...
vm-test-run-horae-e2e-oidc> server # [  145.267410] systemd[1]: Finished Update is Completed.
vm-test-run-horae-e2e-oidc> server # [  146.853776] systemd[1]: suid-sgid-wrappers.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [  146.921843] systemd[1]: Finished Create SUID/SGID Wrappers.
vm-test-run-horae-e2e-oidc> server # [  146.942526] systemd[1]: suid-sgid-wrappers.service: Consumed 2.481s CPU time over 18.644s wall clock time, 4.9M memory peak, 1.9M read from disk.
vm-test-run-horae-e2e-oidc> server # [  151.487026] systemd[1]: Finished Firewall.
vm-test-run-horae-e2e-oidc> server # [  153.011167] systemd[1]: Finished register-nix-paths.service.
vm-test-run-horae-e2e-oidc> server # [  155.181954] systemd-udevd[330]: Using default interface naming scheme 'v260'.
vm-test-run-horae-e2e-oidc> server # [  156.906078] systemd[1]: Started Rule-based Manager for Device Events and Files.
vm-test-run-horae-e2e-oidc> server # [  180.233362] systemd[1]: Finished Coldplug All udev Devices.
vm-test-run-horae-e2e-oidc> server # [  180.253380] systemd[1]: Reached target System Initialization.
vm-test-run-horae-e2e-oidc> server # [  180.281110] systemd[1]: Started Discard unused filesystem blocks once a week.
vm-test-run-horae-e2e-oidc> server # [  180.286719] systemd[1]: Started postgresqlBackup-horae.timer.
vm-test-run-horae-e2e-oidc> server # [  180.298875] systemd[1]: Started Daily Cleanup of Temporary Directories.
vm-test-run-horae-e2e-oidc> server # [  180.316051] systemd[1]: Reached target Timer Units.
vm-test-run-horae-e2e-oidc> server # [  180.340802] systemd[1]: Listening on D-Bus System Message Bus Socket.
vm-test-run-horae-e2e-oidc> server # [  180.346545] systemd[1]: Listening on Nix Daemon Socket.
vm-test-run-horae-e2e-oidc> server # [  180.358350] systemd[1]: Listening on Hostname Service Socket.
vm-test-run-horae-e2e-oidc> server # [  180.370881] systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.
vm-test-run-horae-e2e-oidc> server # [  180.382511] systemd[1]: Reached target Socket Units.
vm-test-run-horae-e2e-oidc> server # [  180.399020] systemd[1]: Reached target Basic System.
vm-test-run-horae-e2e-oidc> server # [  180.474042] systemd[1]: Starting Import lastlog data into lastlog2 database...
vm-test-run-horae-e2e-oidc> server # [  180.681230] systemd[1]: Starting Name Service Cache Daemon (nsncd)...
vm-test-run-horae-e2e-oidc> server # [  180.898989] systemd[1]: Starting Post-Boot Actions...
vm-test-run-horae-e2e-oidc> server # [  181.298753] systemd[1]: Started Reset console on configuration changes.
vm-test-run-horae-e2e-oidc> server # [  181.663578] systemd[1]: Starting resolvconf update...
vm-test-run-horae-e2e-oidc> server # [  182.117459] systemd[1]: Started test-console-diagnostics.service.
vm-test-run-horae-e2e-oidc> server # [  183.057839] systemd[1]: Finished Post-Boot Actions.
vm-test-run-horae-e2e-oidc> server # [  183.122831] nsncd[492]: Nov 03 11:14:18.072 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
vm-test-run-horae-e2e-oidc> server # [  183.161586] systemd[1]: Started Name Service Cache Daemon (nsncd).
vm-test-run-horae-e2e-oidc> server # [  183.841416] systemd[1]: Reached target Host and Network Name Lookups.
vm-test-run-horae-e2e-oidc> server # [  183.873401] systemd[1]: Reached target User and Group Name Lookups.
vm-test-run-horae-e2e-oidc> server # [  184.317982] systemd[1]: Starting D-Bus System Message Bus...
vm-test-run-horae-e2e-oidc> server # [  185.177650] systemd[1]: Starting User Login Management...
vm-test-run-horae-e2e-oidc> server # [  185.423198] systemd[1]: Finished Import lastlog data into lastlog2 database.
vm-test-run-horae-e2e-oidc> server # [  186.891976] test-console-diagnostics-start[527]: JOB UNIT                           TYPE  STATE
vm-test-run-horae-e2e-oidc> server # [  186.926329] test-console-diagnostics-start[527]: 264 network-local-commands.service start waiting
vm-test-run-horae-e2e-oidc> server # [  186.961513] test-console-diagnostics-start[527]: 267 linger-users.service           start waiting
vm-test-run-horae-e2e-oidc> server # [  186.974192] test-console-diagnostics-start[527]: 290 dev-ttyAMA0.device             start running
vm-test-run-horae-e2e-oidc> server # [  186.990972] test-console-diagnostics-start[527]: 272 horae.service                  start waiting
vm-test-run-horae-e2e-oidc> server # [  187.029830] test-console-diagnostics-start[527]: 213 network-pre.target             start waiting
vm-test-run-horae-e2e-oidc> server # [  187.046431] test-console-diagnostics-start[527]: 165 multi-user.target              start waiting
vm-test-run-horae-e2e-oidc> server # [  187.070359] test-console-diagnostics-start[527]: 274 postgresql.service             start waiting
vm-test-run-horae-e2e-oidc> server # [  187.089827] test-console-diagnostics-start[527]: 262 resolvconf.service             start running
vm-test-run-horae-e2e-oidc> server # [  187.114112] test-console-diagnostics-start[527]: 261 dhcpcd.service                 start waiting
vm-test-run-horae-e2e-oidc> server # [  187.137812] test-console-diagnostics-start[527]: 301 dbus-broker.service            start running
vm-test-run-horae-e2e-oidc> server # [  187.155581] test-console-diagnostics-start[527]: 277 systemd-user-sessions.service  start waiting
vm-test-run-horae-e2e-oidc> server # [  187.177786] test-console-diagnostics-start[527]: 288 backdoor.service               start waiting
vm-test-run-horae-e2e-oidc> server # [  187.201673] test-console-diagnostics-start[527]: 257 getty@tty1.service             start waiting
vm-test-run-horae-e2e-oidc> server # [  187.217394] test-console-diagnostics-start[527]: 275 postgresql-setup.service       start waiting
vm-test-run-horae-e2e-oidc> server # [  187.241914] test-console-diagnostics-start[527]: 256 getty.target                   start waiting
vm-test-run-horae-e2e-oidc> server # [  187.273160] test-console-diagnostics-start[527]: 263 network.target                 start waiting
vm-test-run-horae-e2e-oidc> server # [  187.289244] test-console-diagnostics-start[527]: 273 postgresql.target              start waiting
vm-test-run-horae-e2e-oidc> server # [  187.313706] test-console-diagnostics-start[527]: 284 dex.service                    start waiting
vm-test-run-horae-e2e-oidc> server # [  187.325491] test-console-diagnostics-start[527]: 268 systemd-logind.service         start running
vm-test-run-horae-e2e-oidc> server # [  187.341472] test-console-diagnostics-start[527]: 289 dev-hvc0.device                start running
vm-test-run-horae-e2e-oidc> server # [  187.363570] test-console-diagnostics-start[527]: 20 jobs listed.
vm-test-run-horae-e2e-oidc> server # [  187.739097] dbus-broker-launch[513]: Looking up NSS user entry for 'systemd-timesync'...
vm-test-run-horae-e2e-oidc> server # [  188.359211] dbus-broker-launch[513]: NSS returned no entry for 'systemd-timesync'
vm-test-run-horae-e2e-oidc> server # [  188.371413] dbus-broker-launch[513]: Invalid user-name in /nix/store/0xan9m14qz63l4y6vcyfrrbjv937fng3-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"
vm-test-run-horae-e2e-oidc> server # [  188.809883] systemd[1]: Started D-Bus System Message Bus.
vm-test-run-horae-e2e-oidc> server # [  190.075404] dbus-broker-launch[513]: Ready
vm-test-run-horae-e2e-oidc> server # [  190.597347] systemd-logind[517]: New seat seat0.
vm-test-run-horae-e2e-oidc> server # [  190.813519] systemd[1]: Started User Login Management.
vm-test-run-horae-e2e-oidc> server # [  191.043275] test-console-diagnostics-start[539]: Id=backdoor.service
vm-test-run-horae-e2e-oidc> server # [  191.062360] test-console-diagnostics-start[539]: Requires=sysinit.target system.slice dev-hvc0.device dev-ttyAMA0.device
vm-test-run-horae-e2e-oidc> server # [  191.075641] test-console-diagnostics-start[539]: After=dev-ttyAMA0.device sysinit.target system.slice basic.target dev-hvc0.device systemd-journald.socket
vm-test-run-horae-e2e-oidc> server # [  191.086312] test-console-diagnostics-start[539]: ActiveState=inactive
vm-test-run-horae-e2e-oidc> server # [  191.105740] test-console-diagnostics-start[539]: SubState=dead
vm-test-run-horae-e2e-oidc> server # [  191.117821] test-console-diagnostics-start[539]: Result=success
vm-test-run-horae-e2e-oidc> server # [  191.125901] test-console-diagnostics-start[539]: Id=dev-hvc0.device
vm-test-run-horae-e2e-oidc> server # [  191.146365] test-console-diagnostics-start[539]: Requires=
vm-test-run-horae-e2e-oidc> server # [  191.170204] test-console-diagnostics-start[539]: After=
vm-test-run-horae-e2e-oidc> server # [  191.177588] test-console-diagnostics-start[539]: ActiveState=activating
vm-test-run-horae-e2e-oidc> server # [  191.197699] test-console-diagnostics-start[539]: SubState=tentative
vm-test-run-horae-e2e-oidc> server # [  191.214518] test-console-diagnostics-start[539]: Id=dev-ttyAMA0.device
vm-test-run-horae-e2e-oidc> server # [  191.229808] test-console-diagnostics-start[539]: Requires=
vm-test-run-horae-e2e-oidc> server # [  191.241538] test-console-diagnostics-start[539]: After=
vm-test-run-horae-e2e-oidc> server # [  191.261749] test-console-diagnostics-start[539]: ActiveState=activating
vm-test-run-horae-e2e-oidc> server # [  191.274915] test-console-diagnostics-start[539]: SubState=tentative
vm-test-run-horae-e2e-oidc> server # [  191.293436] test-console-diagnostics-start[539]: Id=dev-ttyS0.device
vm-test-run-horae-e2e-oidc> server # [  191.309552] test-console-diagnostics-start[539]: Requires=
vm-test-run-horae-e2e-oidc> server # [  191.322497] test-console-diagnostics-start[539]: After=
vm-test-run-horae-e2e-oidc> server # [  191.353748] test-console-diagnostics-start[539]: ActiveState=inactive
vm-test-run-horae-e2e-oidc> server # [  191.371075] test-console-diagnostics-start[539]: SubState=dead
vm-test-run-horae-e2e-oidc> server # [  191.417199] systemd[1]: Stopped target Host and Network Name Lookups.
vm-test-run-horae-e2e-oidc> server # [  191.434759] systemd[1]: Stopping Host and Network Name Lookups...
vm-test-run-horae-e2e-oidc> server # [  191.458797] systemd[1]: Stopped target User and Group Name Lookups.
vm-test-run-horae-e2e-oidc> server # [  191.479249] systemd[1]: Stopping User and Group Name Lookups...
vm-test-run-horae-e2e-oidc> server # [  191.662002] systemd[1]: Starting linger-users.service...
vm-test-run-horae-e2e-oidc> server # [  191.779497] systemd[1]: Stopping Name Service Cache Daemon (nsncd)...
vm-test-run-horae-e2e-oidc> server # [  191.870779] test-console-diagnostics-start[554]: DEVPATH=/devices/virtual/tty/hvc0
vm-test-run-horae-e2e-oidc> server # [  191.889858] test-console-diagnostics-start[554]: DEVNAME=/dev/hvc0
vm-test-run-horae-e2e-oidc> server # [  191.903119] test-console-diagnostics-start[554]: MAJOR=229
vm-test-run-horae-e2e-oidc> server # [  191.918348] test-console-diagnostics-start[554]: MINOR=0
vm-test-run-horae-e2e-oidc> server # [  191.937005] test-console-diagnostics-start[554]: SUBSYSTEM=tty
vm-test-run-horae-e2e-oidc> server # [  192.119377] systemd[1]: nscd.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [  192.217097] systemd[1]: Stopped Name Service Cache Daemon (nsncd).
vm-test-run-horae-e2e-oidc> server # [  192.226836] systemd[1]: nscd.service: Consumed 582ms CPU time over 11.431s wall clock time, 7.8M memory peak, 5.9M read from disk.
vm-test-run-horae-e2e-oidc> server # [  192.368922] test-console-diagnostics-start[561]: DEVPATH=/devices/platform/9000000.pl011/9000000.pl011:0/9000000.pl011:0.0/tty/ttyAMA0
vm-test-run-horae-e2e-oidc> server # [  192.379647] test-console-diagnostics-start[561]: DEVNAME=/dev/ttyAMA0
vm-test-run-horae-e2e-oidc> server # [  192.407581] test-console-diagnostics-start[561]: MAJOR=204
vm-test-run-horae-e2e-oidc> server # [  192.417587] test-console-diagnostics-start[561]: MINOR=64
vm-test-run-horae-e2e-oidc> server # [  192.431171] test-console-diagnostics-start[561]: SUBSYSTEM=tty
vm-test-run-horae-e2e-oidc> server # [  192.839900] test-console-diagnostics-start[568]: DEVPATH=/devices/platform/serial8250/serial8250:0/serial8250:0.0/tty/ttyS0
vm-test-run-horae-e2e-oidc> server # [  192.881180] test-console-diagnostics-start[568]: DEVNAME=/dev/ttyS0
vm-test-run-horae-e2e-oidc> server # [  192.889553] test-console-diagnostics-start[568]: MAJOR=4
vm-test-run-horae-e2e-oidc> server # [  192.918045] test-console-diagnostics-start[568]: MINOR=64
vm-test-run-horae-e2e-oidc> server # [  192.938244] test-console-diagnostics-start[568]: SUBSYSTEM=tty
vm-test-run-horae-e2e-oidc> server # [  193.274511] systemd[1]: Starting Name Service Cache Daemon (nsncd)...
vm-test-run-horae-e2e-oidc> server # [  193.623271] systemd[1]: Finished resolvconf update.
vm-test-run-horae-e2e-oidc> server # [  193.729136] systemd[1]: linger-users.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [  193.777252] systemd[1]: Finished linger-users.service.
vm-test-run-horae-e2e-oidc> server # [  193.986171] systemd[1]: Reached target Preparation for Network.
vm-test-run-horae-e2e-oidc> server # [  194.306779] systemd[1]: Starting DHCP Client...
vm-test-run-horae-e2e-oidc> server # [  194.577979] systemd[1]: Starting Extra networking commands....
vm-test-run-horae-e2e-oidc> server # [  194.693408] nsncd[575]: Nov 03 11:14:29.708 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
vm-test-run-horae-e2e-oidc> server # [  194.810742] systemd[1]: Started Name Service Cache Daemon (nsncd).
vm-test-run-horae-e2e-oidc> server # [  194.941019] systemd[1]: Reached target Host and Network Name Lookups.
vm-test-run-horae-e2e-oidc> server # [  195.001165] systemd[1]: Reached target User and Group Name Lookups.
vm-test-run-horae-e2e-oidc> server # [  200.022437] systemd[1]: Finished Extra networking commands..
vm-test-run-horae-e2e-oidc> server # [  200.107926] systemd[1]: Reached target Network.
vm-test-run-horae-e2e-oidc> server # [  200.457987] dhcpcd[596]: dhcpcd-10.3.2 starting
vm-test-run-horae-e2e-oidc> server # [  200.490434] systemd[1]: Starting dex identity provider...
vm-test-run-horae-e2e-oidc> server # [  200.647613] dhcpcd[639]: dev: loaded udev
vm-test-run-horae-e2e-oidc> server # [  200.885374] dhcpcd[639]: no valid interfaces found
vm-test-run-horae-e2e-oidc> server # [  200.898264] dhcpcd[639]: no valid interfaces found
vm-test-run-horae-e2e-oidc> server # [  200.932981] dhcpcd[639]: libudev: received NULL device
vm-test-run-horae-e2e-oidc> server # [  200.946238] dhcpcd[639]: libudev: received NULL device
vm-test-run-horae-e2e-oidc> server # [  200.969343] systemd[1]: Starting PostgreSQL Server...
vm-test-run-horae-e2e-oidc> server # [  201.271148] systemd[1]: Starting Permit User Sessions...
vm-test-run-horae-e2e-oidc> server # [  202.922885] systemd[1]: Finished Permit User Sessions.
vm-test-run-horae-e2e-oidc> server # [  203.213941] systemd[1]: Started Getty on tty1.
vm-test-run-horae-e2e-oidc> server # [  203.310242] systemd[1]: Reached target Login Prompts.
vm-test-run-horae-e2e-oidc> server # [  207.466502] postgresql-pre-start[650]: The files belonging to this database system will be owned by user "postgres".
vm-test-run-horae-e2e-oidc> server # [  207.479322] postgresql-pre-start[650]: This user must also own the server process.
vm-test-run-horae-e2e-oidc> server # [  207.562959] postgresql-pre-start[650]: The database cluster will be initialized with locale "en_US.UTF-8".
vm-test-run-horae-e2e-oidc> server # [  207.578325] postgresql-pre-start[650]: The default database encoding has accordingly been set to "UTF8".
vm-test-run-horae-e2e-oidc> server # [  207.597674] postgresql-pre-start[650]: The default text search configuration will be set to "english".
vm-test-run-horae-e2e-oidc> server # [  207.607117] postgresql-pre-start[650]: Data page checksums are disabled.
vm-test-run-horae-e2e-oidc> server # [  207.661916] systemd[1]: Started dex identity provider.
vm-test-run-horae-e2e-oidc> server # [  207.674053] postgresql-pre-start[650]: fixing permissions on existing directory /var/lib/postgresql/17 ... ok
vm-test-run-horae-e2e-oidc> server # [  207.871531] postgresql-pre-start[650]: creating subdirectories ... ok
vm-test-run-horae-e2e-oidc> server # [  207.905716] postgresql-pre-start[650]: selecting dynamic shared memory implementation ... posix
vm-test-run-horae-e2e-oidc> server # [  210.630056] postgresql-pre-start[650]: selecting default "max_connections" ... 100
vm-test-run-horae-e2e-oidc> server # [  212.689671] postgresql-pre-start[650]: selecting default "shared_buffers" ... 128MB
vm-test-run-horae-e2e-oidc> server # [  217.018265] dex[655]: time=2026-11-03T11:14:52.005Z level=INFO msg="Version info" dex_version=v2.45.1 go.version=go1.26.4 go.os=linux go.arch=arm64
vm-test-run-horae-e2e-oidc> server # [  217.051186] dex[655]: time=2026-11-03T11:14:52.056Z level=INFO msg="config issuer" issuer=http://127.0.0.1:5556/dex
vm-test-run-horae-e2e-oidc> server # [  217.066670] dex[655]: time=2026-11-03T11:14:52.108Z level=INFO msg="config storage" storage_type=memory
vm-test-run-horae-e2e-oidc> server # [  217.081551] dex[655]: time=2026-11-03T11:14:52.109Z level=INFO msg="config static client" client_name=Horae
vm-test-run-horae-e2e-oidc> server # [  217.098231] dex[655]: time=2026-11-03T11:14:52.109Z level=INFO msg="config static client" client_name="Horae without email_verified"
vm-test-run-horae-e2e-oidc> server # [  217.121819] dex[655]: time=2026-11-03T11:14:52.110Z level=INFO msg="config connector" connector_id=mock
vm-test-run-horae-e2e-oidc> server # [  217.133887] dex[655]: time=2026-11-03T11:14:52.121Z level=INFO msg="config skipping approval screen"
vm-test-run-horae-e2e-oidc> server # [  217.164964] dex[655]: time=2026-11-03T11:14:52.122Z level=INFO msg="continue on connector failure feature flag enabled"
vm-test-run-horae-e2e-oidc> server # [  217.181998] dex[655]: time=2026-11-03T11:14:52.137Z level=INFO msg="signer configured" type=local keys_rotation_period=6h
vm-test-run-horae-e2e-oidc> server # [  217.189970] dex[655]: time=2026-11-03T11:14:52.138Z level=INFO msg="config refresh tokens rotation" enabled=true
vm-test-run-horae-e2e-oidc> server # [  217.254038] dex[655]: time=2026-11-03T11:14:52.312Z level=ERROR msg="failed to get signing algorithm" err="no signing key found"
vm-test-run-horae-e2e-oidc> server # [  217.330969] dex[655]: time=2026-11-03T11:14:52.390Z level=INFO msg="keys expired, rotating"
vm-test-run-horae-e2e-oidc> server # [  219.102640] dex[655]: time=2026-11-03T11:14:54.121Z level=INFO msg="keys rotated" next_rotation=2026-11-03T17:14:54.121Z
vm-test-run-horae-e2e-oidc> server # [  219.114382] dex[655]: time=2026-11-03T11:14:54.163Z level=INFO msg="listening on" server=http address=127.0.0.1:5556
vm-test-run-horae-e2e-oidc> server # [  230.983143] dhcpcd[639]: timed out
vm-test-run-horae-e2e-oidc> server # [  231.014155] dhcpcd[639]: timed out
vm-test-run-horae-e2e-oidc> server # [  231.099777] systemd[1]: Started DHCP Client.
vm-test-run-horae-e2e-oidc> server # [  238.689974] postgresql-pre-start[650]: selecting default time zone ... UTC
vm-test-run-horae-e2e-oidc> server # [  238.737309] postgresql-pre-start[650]: creating configuration files ... ok
vm-test-run-horae-e2e-oidc> server # [  250.990089] postgresql-pre-start[650]: running bootstrap script ... ok
vm-test-run-horae-e2e-oidc> server # [  254.011552] test-console-diagnostics-start[675]: JOB UNIT                     TYPE  STATE
vm-test-run-horae-e2e-oidc> server # [  254.031238] test-console-diagnostics-start[675]: 290 dev-ttyAMA0.device       start running
vm-test-run-horae-e2e-oidc> server # [  254.054012] test-console-diagnostics-start[675]: 272 horae.service            start waiting
vm-test-run-horae-e2e-oidc> server # [  254.073787] test-console-diagnostics-start[675]: 165 multi-user.target        start waiting
vm-test-run-horae-e2e-oidc> server # [  254.082159] test-console-diagnostics-start[675]: 274 postgresql.service       start running
vm-test-run-horae-e2e-oidc> server # [  254.094194] test-console-diagnostics-start[675]: 288 backdoor.service         start waiting
vm-test-run-horae-e2e-oidc> server # [  254.110211] test-console-diagnostics-start[675]: 275 postgresql-setup.service start waiting
vm-test-run-horae-e2e-oidc> server # [  254.126239] test-console-diagnostics-start[675]: 273 postgresql.target        start waiting
vm-test-run-horae-e2e-oidc> server # [  254.142106] test-console-diagnostics-start[675]: 289 dev-hvc0.device          start running
vm-test-run-horae-e2e-oidc> server # [  254.151144] test-console-diagnostics-start[675]: 8 jobs listed.
vm-test-run-horae-e2e-oidc> server # [  254.449006] input: QEMU Virtio Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:09.0/virtio8/input/input3
vm-test-run-horae-e2e-oidc> server # [  255.311287] test-console-diagnostics-start[676]: Id=backdoor.service
vm-test-run-horae-e2e-oidc> server # [  255.342725] test-console-diagnostics-start[676]: Requires=sysinit.target system.slice dev-hvc0.device dev-ttyAMA0.device
vm-test-run-horae-e2e-oidc> server # [  255.355611] test-console-diagnostics-start[676]: After=dev-ttyAMA0.device sysinit.target system.slice basic.target dev-hvc0.device systemd-journald.socket
vm-test-run-horae-e2e-oidc> server # [  255.366255] test-console-diagnostics-start[676]: ActiveState=inactive
vm-test-run-horae-e2e-oidc> server # [  255.381443] test-console-diagnostics-start[676]: SubState=dead
vm-test-run-horae-e2e-oidc> server # [  255.393459] test-console-diagnostics-start[676]: Result=success
vm-test-run-horae-e2e-oidc> server # [  255.405738] test-console-diagnostics-start[676]: Id=dev-hvc0.device
vm-test-run-horae-e2e-oidc> server # [  255.417365] test-console-diagnostics-start[676]: Requires=
vm-test-run-horae-e2e-oidc> server # [  255.422754] test-console-diagnostics-start[676]: After=
vm-test-run-horae-e2e-oidc> server # [  255.437683] test-console-diagnostics-start[676]: ActiveState=activating
vm-test-run-horae-e2e-oidc> server # [  255.453836] test-console-diagnostics-start[676]: SubState=tentative
vm-test-run-horae-e2e-oidc> server # [  255.461805] test-console-diagnostics-start[676]: Id=dev-ttyAMA0.device
vm-test-run-horae-e2e-oidc> server # [  255.473737] test-console-diagnostics-start[676]: Requires=
vm-test-run-horae-e2e-oidc> server # [  255.489601] test-console-diagnostics-start[676]: After=
vm-test-run-horae-e2e-oidc> server # [  255.491606] test-console-diagnostics-start[676]: ActiveState=activating
vm-test-run-horae-e2e-oidc> server # [  255.506726] test-console-diagnostics-start[676]: SubState=tentative
vm-test-run-horae-e2e-oidc> server # [  255.521327] test-console-diagnostics-start[676]: Id=dev-ttyS0.device
vm-test-run-horae-e2e-oidc> server # [  255.525236] test-console-diagnostics-start[676]: Requires=
vm-test-run-horae-e2e-oidc> server # [  255.541363] test-console-diagnostics-start[676]: After=
vm-test-run-horae-e2e-oidc> server # [  255.549462] test-console-diagnostics-start[676]: ActiveState=inactive
vm-test-run-horae-e2e-oidc> server # [  255.561482] test-console-diagnostics-start[676]: SubState=dead
vm-test-run-horae-e2e-oidc> server # [  255.693651] test-console-diagnostics-start[677]: DEVPATH=/devices/virtual/tty/hvc0
vm-test-run-horae-e2e-oidc> server # [  255.702915] test-console-diagnostics-start[677]: DEVNAME=/dev/hvc0
vm-test-run-horae-e2e-oidc> server # [  255.714440] test-console-diagnostics-start[677]: MAJOR=229
vm-test-run-horae-e2e-oidc> server # [  255.734114] test-console-diagnostics-start[677]: MINOR=0
vm-test-run-horae-e2e-oidc> server # [  255.745447] test-console-diagnostics-start[677]: SUBSYSTEM=tty
vm-test-run-horae-e2e-oidc> server # [  256.031399] test-console-diagnostics-start[678]: DEVPATH=/devices/platform/9000000.pl011/9000000.pl011:0/9000000.pl011:0.0/tty/ttyAMA0
vm-test-run-horae-e2e-oidc> server # [  256.054872] test-console-diagnostics-start[678]: DEVNAME=/dev/ttyAMA0
vm-test-run-horae-e2e-oidc> server # [  256.075768] test-console-diagnostics-start[678]: MAJOR=204
vm-test-run-horae-e2e-oidc> server # [  256.086868] test-console-diagnostics-start[678]: MINOR=64
vm-test-run-horae-e2e-oidc> server # [  256.101916] test-console-diagnostics-start[678]: SUBSYSTEM=tty
vm-test-run-horae-e2e-oidc> server # [  256.378436] test-console-diagnostics-start[679]: DEVPATH=/devices/platform/serial8250/serial8250:0/serial8250:0.0/tty/ttyS0
vm-test-run-horae-e2e-oidc> server # [  256.390114] test-console-diagnostics-start[679]: DEVNAME=/dev/ttyS0
vm-test-run-horae-e2e-oidc> server # [  256.409460] test-console-diagnostics-start[679]: MAJOR=4
vm-test-run-horae-e2e-oidc> server # [  256.417993] test-console-diagnostics-start[679]: MINOR=64
vm-test-run-horae-e2e-oidc> server # [  256.429439] test-console-diagnostics-start[679]: SUBSYSTEM=tty
vm-test-run-horae-e2e-oidc> server # [  273.609806] systemd[1]: Starting Virtual Console Setup...
vm-test-run-horae-e2e-oidc> server # [  277.219166] systemd-vconsole-setup[686]: Configuration of first virtual console was skipped, ignoring remaining ones.
vm-test-run-horae-e2e-oidc> server # [  277.354006] systemd[1]: Finished Virtual Console Setup.
vm-test-run-horae-e2e-oidc> server # [  277.597733] systemd[1]: Load Kernel Module configfs skipped, unmet condition check ConditionKernelModuleLoaded=!configfs
vm-test-run-horae-e2e-oidc> server # [  286.866228] postgresql-pre-start[650]: performing post-bootstrap initialization ... ok
vm-test-run-horae-e2e-oidc> server # [  287.011210] systemd[1]: Condition check resulted in /dev/hvc0 being skipped.
vm-test-run-horae-e2e-oidc> server # [  289.303150] 8021q: 802.1Q VLAN Support v1.8
vm-test-run-horae-e2e-oidc> server # [  291.138342] cfg80211: Loading compiled-in X.509 certificates for regulatory database
vm-test-run-horae-e2e-oidc> server # [  291.486834] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
vm-test-run-horae-e2e-oidc> server # [  291.518699] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'
vm-test-run-horae-e2e-oidc> server # [  291.586254] faux_driver regulatory: Direct firmware load for regulatory.db failed with error -2
vm-test-run-horae-e2e-oidc> server # [  291.455190] systemd[1]: Condition check resulted in /dev/ttyAMA0 being skipped.
vm-test-run-horae-e2e-oidc> server # [  291.617082] cfg80211: failed to load regulatory.db
vm-test-run-horae-e2e-oidc> server # [  291.701336] systemd[1]: Started backdoor.service.
vm-test-run-horae-e2e-oidc> server # [  293.629936] (udev-worker)[487]: eth1: Config file /etc/systemd/network/40-eth1.link is applied to device based on potentially unpredictable interface name.
vm-test-run-horae-e2e-oidc> server # connecting to host...
vm-test-run-horae-e2e-oidc> server # [  293.699548] (udev-worker)[486]: Network interface NamePolicy= disabled on kernel command line.
vm-test-run-horae-e2e-oidc> server # [  293.749458] (udev-worker)[487]: Network interface NamePolicy= disabled on kernel command line.
vm-test-run-horae-e2e-oidc> server: waiting for unit register-nix-paths.service
vm-test-run-horae-e2e-oidc> server: waiting for the VM to finish booting
vm-test-run-horae-e2e-oidc> server: Guest shell says: b'Spawning backdoor root shell...\n'
vm-test-run-horae-e2e-oidc> server: connected to guest root shell
vm-test-run-horae-e2e-oidc> server: (connecting took 0.00 seconds)
vm-test-run-horae-e2e-oidc> server: (finished: waiting for the VM to finish booting, in 0.00 seconds)
vm-test-run-horae-e2e-oidc> server # [  296.222562] postgresql-pre-start[650]: syncing data to disk ... ok
vm-test-run-horae-e2e-oidc> server # [  296.252825] postgresql-pre-start[650]: initdb: warning: enabling "trust" authentication for local connections
vm-test-run-horae-e2e-oidc> server # [  296.255196] postgresql-pre-start[650]: 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.
vm-test-run-horae-e2e-oidc> server # [  296.275998] postgresql-pre-start[650]: Success. You can now start the database server using:
vm-test-run-horae-e2e-oidc> server # [  296.290429] postgresql-pre-start[650]:     pg_ctl -D /var/lib/postgresql/17 -l logfile start
vm-test-run-horae-e2e-oidc> server: (finished: waiting for unit register-nix-paths.service, in 2.35 seconds)
vm-test-run-horae-e2e-oidc> server: waiting for unit postgresql.service
vm-test-run-horae-e2e-oidc> server # [  297.482101] systemd[1]: Condition check resulted in Virtio network device being skipped.
vm-test-run-horae-e2e-oidc> server # [  298.958883] systemd[1]: Starting Address configuration of eth1...
vm-test-run-horae-e2e-oidc> server # [  300.285550] 8021q: adding VLAN 0 to HW filter on device eth0
vm-test-run-horae-e2e-oidc> server # [  300.218736] dhcpcd[639]: eth0: waiting for carrier
vm-test-run-horae-e2e-oidc> server # [  300.239224] dhcpcd[639]: eth0: carrier acquired
vm-test-run-horae-e2e-oidc> server # [  300.743177] dhcpcd[639]: DUID 00:01:00:01:32:7c:7e:ff:52:54:00:12:34:56
vm-test-run-horae-e2e-oidc> server # [  300.759619] dhcpcd[639]: eth0: IAID 00:12:34:56
vm-test-run-horae-e2e-oidc> server # [  300.775919] dhcpcd[639]: eth0: adding address fe80::5054:ff:fe12:3456
vm-test-run-horae-e2e-oidc> server # [  301.561654] 8021q: adding VLAN 0 to HW filter on device eth1
vm-test-run-horae-e2e-oidc> server # [  301.938660] network-addresses-eth1-start[721]: adding address 192.168.1.1/24... done
vm-test-run-horae-e2e-oidc> server # [  302.011904] dhcpcd[639]: eth0: soliciting a DHCP lease
vm-test-run-horae-e2e-oidc> server # [  302.031778] dhcpcd[639]: eth0: offered 10.0.2.15 from 10.0.2.2
vm-test-run-horae-e2e-oidc> server # [  302.051259] dhcpcd[639]: eth0: probing address 10.0.2.15/24
vm-test-run-horae-e2e-oidc> server # [  302.285978] network-addresses-eth1-start[721]: adding address 2001:db8:1::1/64... done
vm-test-run-horae-e2e-oidc> server # [  302.797718] systemd[1]: Finished Address configuration of eth1.
vm-test-run-horae-e2e-oidc> server # [  303.562519] dhcpcd[639]: eth0: soliciting an IPv6 router
vm-test-run-horae-e2e-oidc> server # [  303.591109] dhcpcd[639]: eth0: Router Advertisement from fe80::2
vm-test-run-horae-e2e-oidc> server # [  303.620843] dhcpcd[639]: eth0: adding address fec0::5054:ff:fe12:3456/64
vm-test-run-horae-e2e-oidc> server # [  303.661336] dhcpcd[639]: eth0: adding route to fec0::/64
vm-test-run-horae-e2e-oidc> server # [  303.681533] dhcpcd[639]: eth0: adding default route via fe80::2
vm-test-run-horae-e2e-oidc> server # [  304.401083] postgres[714]: [714] LOG:  starting PostgreSQL 17.10 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit
vm-test-run-horae-e2e-oidc> server # [  304.497161] postgres[714]: [714] LOG:  listening on IPv6 address "::1", port 5432
vm-test-run-horae-e2e-oidc> server # [  304.499023] postgres[714]: [714] LOG:  listening on IPv4 address "127.0.0.1", port 5432
vm-test-run-horae-e2e-oidc> server # [  304.537267] postgres[714]: [714] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
vm-test-run-horae-e2e-oidc> server # [  304.867730] postgres[748]: [748] LOG:  database system was shut down at 2026-11-03 11:16:01 GMT
vm-test-run-horae-e2e-oidc> server # [  305.258247] postgres[714]: [714] LOG:  database system is ready to accept connections
vm-test-run-horae-e2e-oidc> server # [  305.375953] systemd[1]: Started PostgreSQL Server.
vm-test-run-horae-e2e-oidc> server # [  305.554246] systemd[1]: Starting PostgreSQL Setup Scripts...
vm-test-run-horae-e2e-oidc> server: (finished: waiting for unit postgresql.service, in 11.18 seconds)
vm-test-run-horae-e2e-oidc> server: waiting for unit dex.service
vm-test-run-horae-e2e-oidc> server # [  308.495758] dhcpcd[639]: eth0: leased 10.0.2.15 for 86400 seconds
vm-test-run-horae-e2e-oidc> server # [  308.515244] dhcpcd[639]: eth0: adding route to 10.0.2.0/24
vm-test-run-horae-e2e-oidc> server # [  308.531033] dhcpcd[639]: eth0: adding default route via 10.0.2.2
vm-test-run-horae-e2e-oidc> server: (finished: waiting for unit dex.service, in 2.67 seconds)
vm-test-run-horae-e2e-oidc> server: waiting for unit horae.service
vm-test-run-horae-e2e-oidc> server # [  317.225447] systemd[1]: test-console-diagnostics.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [  317.262866] systemd[1]: test-console-diagnostics.service: Consumed 1.773s CPU time over 2min 15.087s wall clock time, 9.3M memory peak, 7.3M read from disk.
vm-test-run-horae-e2e-oidc> server # [  317.455325] postgresql-setup-start[776]: CREATE DATABASE
vm-test-run-horae-e2e-oidc> server # [  318.876050] postgresql-setup-start[842]: CREATE ROLE
vm-test-run-horae-e2e-oidc> server # [  319.261444] systemd-logind[517]: Watching system buttons on /dev/input/event1 (gpio-keys)
vm-test-run-horae-e2e-oidc> server # [  319.507905] postgresql-setup-start[844]: ALTER ROLE
vm-test-run-horae-e2e-oidc> server # [  320.233969] postgresql-setup-start[850]: ALTER DATABASE
vm-test-run-horae-e2e-oidc> server # [  320.457987] systemd[1]: Finished PostgreSQL Setup Scripts.
vm-test-run-horae-e2e-oidc> server # [  320.662248] systemd[1]: Reached target PostgreSQL.
vm-test-run-horae-e2e-oidc> server # [  320.869285] systemd[1]: Starting Horae time tracking server...
vm-test-run-horae-e2e-oidc> server # [  324.646018] horae[856]: 2026-11-03T11:16:39.664765Z  INFO horae: Running migrations...
vm-test-run-horae-e2e-oidc> server # [  325.685018] mousedev: PS/2 mouse device common for all mice
vm-test-run-horae-e2e-oidc> server # [  327.470110] horae[856]: 2026-11-03T11:16:42.482358Z  WARN sqlx::query: slow statement: execution time exceeded alert threshold summary="-- Horae Phase 1 …" db.statement="\n\n-- Horae Phase 1 schema\n-- All IDs are UUID v7 (time-ordered).\n-- Time stored as integer minutes; money as integer cents + ISO 4217 currency.\n\n-- ── Enum types ───────────────────────────────────────────────────────────────\n\nCREATE TYPE org_role     AS ENUM ('admin', 'manager', 'member');\nCREATE TYPE project_role AS ENUM ('lead', 'freelancer', 'admin');\nCREATE TYPE project_type AS ENUM ('time_and_materials', 'fixed_fee', 'non_billable', 'retainer');\nCREATE TYPE entry_state  AS ENUM ('open', 'submitted', 'approved', 'invoiced');\nCREATE TYPE budget_kind  AS ENUM ('none', 'amount', 'hours');\nCREATE TYPE round_dir    AS ENUM ('nearest', 'up', 'down');\n\n-- ── Tables ───────────────────────────────────────────────────────────────────\n\nCREATE TABLE organizations (\n  id               uuid        PRIMARY KEY,\n  name             text        NOT NULL,\n  default_currency char(3)     NOT NULL DEFAULT 'EUR',\n  week_start       smallint    NOT NULL DEFAULT 1,       -- 1 = Monday\n  round_minutes    smallint    NOT NULL DEFAULT 0,       -- 0 = no rounding\n  round_dir        round_dir   NOT NULL DEFAULT 'nearest',\n  created_at       timestamptz NOT NULL DEFAULT now()\n);\n\nCREATE TABLE users (\n  id                   uuid     PRIMARY KEY,\n  org_id               uuid     NOT NULL REFERENCES organizations(id),\n  email                text     NOT NULL UNIQUE,\n  name                 text     NOT NULL,\n  oidc_subject         text     UNIQUE,                  -- null until first OIDC login\n  org_role             org_role NOT NULL DEFAULT 'member',\n  cost_rate_cents      bigint,\n  billable_rate_cents  bigint,\n  active               boolean  NOT NULL DEFAULT true,\n  created_at           timestamptz NOT NULL DEFAULT now()\n);\n\nCREATE TABLE clients (\n  id         uuid        PRIMARY KEY,\n  org_id     uuid        NOT NULL REFERENCES organizations(id),\n  name       text        NOT NULL,\n  currency   char(3)     NOT NULL,\n  address    text,\n  tax_id     text,\n  active     boolean     NOT NULL DEFAULT true,\n  created_at timestamptz NOT NULL DEFAULT now()\n);\n\nCREATE TABLE projects (\n  id                  uuid         PRIMARY KEY,\n  org_id              uuid         NOT NULL REFERENCES organizations(id),\n  client_id           uuid         NOT NULL REFERENCES clients(id),\n  code                text,\n  name                text         NOT NULL,\n  project_type        project_type NOT NULL DEFAULT 'time_and_materials',\n  currency            char(3)      NOT NULL,\n  starts_on           date,\n  ends_on             date,\n  budget_kind         budget_kind  NOT NULL DEFAULT 'none',\n  budget_amount_cents bigint,\n  budget_minutes      bigint,\n  active              boolean      NOT NULL DEFAULT true,\n  created_at          timestamptz  NOT NULL DEFAULT now()\n);\n\nCREATE TABLE tasks (                                      -- org-level task catalog\n  id                 uuid    PRIMARY KEY,\n  org_id             uuid    NOT NULL REFERENCES organizations(id),\n  name               text    NOT NULL,\n  billable_default   boolean NOT NULL DEFAULT true,\n  default_rate_cents bigint,\n  active             boolean NOT NULL DEFAULT true\n);\n\nCREATE TABLE project_tasks (                              -- task enabled per project + overrides\n  project_id uuid    NOT NULL REFERENCES projects(id),\n  task_id    uuid    NOT NULL REFERENCES tasks(id),\n  billable   boolean NOT NULL,\n  rate_cents bigint,\n  PRIMARY KEY (project_id, task_id)\n);\n\nCREATE TABLE assignments (\n  id         uuid         PRIMARY KEY,\n  project_id uuid         NOT NULL REFERENCES projects(id),\n  user_id    uuid         NOT NULL REFERENCES users(id),\n  role       project_role NOT NULL DEFAULT 'freelancer',\n  rate_cents bigint,\n  created_at timestamptz  NOT NULL DEFAULT now(),\n  UNIQUE (project_id, user_id)\n);\n\nCREATE TABLE time_entries (\n  id              uuid        PRIMARY KEY,\n  org_id          uuid        NOT NULL REFERENCES organizations(id),\n  user_id         uuid        NOT NULL REFERENCES users(id),\n  project_id      uuid        NOT NULL REFERENCES projects(id),\n  task_id         uuid        NOT NULL REFERENCES tasks(id),\n  spent_date      date        NOT NULL,\n  minutes         integer     NOT NULL DEFAULT 0,\n  rounded_minutes integer,                               -- persisted at lock (submit)\n  notes           text,\n  billable        boolean     NOT NULL,\n  is_running      boolean     NOT NULL DEFAULT false,\n  started_at      timestamptz,                           -- non-null only while running\n  state           entry_state NOT NULL DEFAULT 'open',\n  invoice_id      uuid,                                  -- Phase 4\n  created_at      timestamptz NOT NULL DEFAULT now(),\n  updated_at      timestamptz NOT NULL DEFAULT now()\n);\n\nCREATE INDEX ON time_entries (user_id, spent_date);\nCREATE INDEX ON time_entries (project_id, spent_date);\n\n-- Enforces the one-running-timer-per-user invariant at the database level.\nCREATE UNIQUE INDEX one_running_timer_per_user ON time_entries (user_id) WHERE is_running;\n\nCREATE TABLE approvals (\n  id           uuid        PRIMARY KEY,\n  org_id       uuid        NOT NULL REFERENCES organizations(id),\n  user_id      uuid        NOT NULL REFERENCES users(id),\n  period_start date        NOT NULL,\n  period_end   date        NOT NULL,\n  state        entry_state NOT NULL DEFAULT 'submitted', -- reject deletes the row\n  submitted_at timestamptz NOT NULL DEFAULT now(),\n  approved_by  uuid        REFERENCES users(id),\n  approved_at  timestamptz,\n  UNIQUE (user_id, period_start)\n);\n\nCREATE TABLE audit_log (\n  id            uuid        PRIMARY KEY,\n  org_id        uuid        NOT NULL,\n  actor_user_id uuid,\n  action        text        NOT NULL,                    -- e.g. 'entry.submit'\n  entity_type   text        NOT NULL,\n  entity_id     uuid,\n  data          jsonb,\n  created_at    timestamptz NOT NULL DEFAULT now()\n);\n\n" rows_affected=0 rows_returned=0 elapsed=2.268408986s elapsed_secs=2.268408986 slow_threshold=1s
vm-test-run-horae-e2e-oidc> server # [  330.378451] systemd-logind[517]: Watching system buttons on /dev/input/event0 (QEMU QEMU USB Keyboard)
vm-test-run-horae-e2e-oidc> server # [  337.131695] horae[856]: 2026-11-03T11:16:52.157384Z  WARN sqlx::query: slow statement: execution time exceeded alert threshold summary="-- New creation settings …" db.statement="\n\n-- New creation settings are opt-in. Existing and imported projects retain the\n-- legacy billing cascade when no project_settings row exists.\nALTER TABLE users ADD CONSTRAINT users_id_org_unique UNIQUE (id, org_id);\nALTER TABLE projects ADD CONSTRAINT projects_id_org_unique UNIQUE (id, org_id);\nALTER TABLE tasks ADD CONSTRAINT tasks_id_org_unique UNIQUE (id, org_id);\n\nALTER TABLE clients ADD COLUMN default_rate_cents bigint\n  CHECK (default_rate_cents IS NULL OR default_rate_cents >= 0);\n\nCREATE TABLE project_drafts (\n  id                   uuid PRIMARY KEY,\n  org_id               uuid NOT NULL REFERENCES organizations(id),\n  creator_id           uuid NOT NULL,\n  revision             bigint NOT NULL DEFAULT 1 CHECK (revision > 0),\n  payload_version      smallint NOT NULL DEFAULT 1 CHECK (payload_version = 1),\n  payload              jsonb NOT NULL CHECK (\n                         jsonb_typeof(payload) = 'object'\n                         AND octet_length(payload::text) <= 262144),\n  completed_project_id uuid,\n  discarded_at         timestamptz,\n  created_at           timestamptz NOT NULL DEFAULT now(),\n  updated_at           timestamptz NOT NULL DEFAULT now(),\n  FOREIGN KEY (creator_id, org_id) REFERENCES users(id, org_id),\n  FOREIGN KEY (completed_project_id, org_id) REFERENCES projects(id, org_id),\n  CHECK (completed_project_id IS NULL OR discarded_at IS NULL)\n);\n\nCREATE UNIQUE INDEX project_drafts_current_creator_idx\n  ON project_drafts (org_id, creator_id)\n  WHERE completed_project_id IS NULL AND discarded_at IS NULL;\n\nCREATE TABLE project_settings (\n  id                  uuid PRIMARY KEY,\n  org_id              uuid NOT NULL REFERENCES organizations(id),\n  project_id          uuid NOT NULL UNIQUE,\n  creator_id          uuid NOT NULL,\n  rate_mode           text NOT NULL CHECK (rate_mode IN ('person', 'task', 'project')),\n  budget_scope        text NOT NULL DEFAULT 'project'\n                      CHECK (budget_scope IN ('project', 'task', 'person')),\n  monthly_reset       boolean NOT NULL DEFAULT false,\n  include_nonbillable boolean NOT NULL DEFAULT false,\n  alert_enabled       boolean NOT NULL DEFAULT false,\n  alert_threshold     smallint NOT NULL DEFAULT 80 CHECK (alert_threshold BETWEEN 0 AND 100),\n  report_visibility   text NOT NULL DEFAULT 'managers'\n                      CHECK (report_visibility IN ('managers', 'project_members')),\n  fee_mode            text CHECK (fee_mode IN ('single', 'milestones', 'monthly')),\n  fee_amount_cents    bigint CHECK (fee_amount_cents >= 0),\n  monthly_day         text CHECK (monthly_day IN ('first', 'fifteenth', 'last')),\n  terms_days          smallint NOT NULL DEFAULT 30 CHECK (terms_days BETWEEN 0 AND 365),\n  po_number           text NOT NULL DEFAULT '' CHECK (char_length(po_number) <= 200),\n  discount_bps        smallint NOT NULL DEFAULT 0 CHECK (discount_bps BETWEEN 0 AND 10000),\n  tax1_bps            smallint NOT NULL DEFAULT 0 CHECK (tax1_bps BETWEEN 0 AND 10000),\n  tax2_name           text CHECK (char_length(btrim(tax2_name)) BETWEEN 1 AND 100),\n  tax2_bps            smallint CHECK (tax2_bps BETWEEN 0 AND 10000),\n  FOREIGN KEY (project_id, org_id) REFERENCES projects(id, org_id) ON DELETE CASCADE,\n  FOREIGN KEY (creator_id, org_id) REFERENCES users(id, org_id),\n  CHECK ((tax2_name IS NULL) = (tax2_bps IS NULL)),\n  CHECK (CASE fee_mode\n    WHEN 'single' THEN fee_amount_cents IS NOT NULL AND monthly_day IS NULL\n    WHEN 'milestones' THEN fee_amount_cents IS NULL AND monthly_day IS NULL\n    WHEN 'monthly' THEN fee_amount_cents IS NOT NULL AND monthly_day IS NOT NULL\n    ELSE fee_amount_cents IS NULL AND monthly_day IS NULL\n  END)\n);\n\n-- Private fields must not inherit table-level SELECT grants on projects or\n-- assignments held by the plugin database role.\nCREATE TABLE project_private_settings (\n  id          uuid PRIMARY KEY,\n  org_id      uuid NOT NULL REFERENCES organizations(id),\n  project_id  uuid NOT NULL UNIQUE,\n  admin_notes text NOT NULL DEFAULT '' CHECK (char_length(admin_notes) <= 10000),\n  FOREIGN KEY (project_id, org_id) REFERENCES projects(id, org_id) ON DELETE CASCADE\n);\n\nCREATE TABLE project_member_costs (\n  id              uuid PRIMARY KEY,\n  org_id          uuid NOT NULL REFERENCES organizations(id),\n  project_id      uuid NOT NULL,\n  user_id         uuid NOT NULL,\n  cost_rate_cents bigint NOT NULL CHECK (cost_rate_cents >= 0),\n  UNIQUE (project_id, user_id),\n  FOREIGN KEY (project_id, org_id) REFERENCES projects(id, org_id) ON DELETE CASCADE,\n  FOREIGN KEY (user_id, org_id) REFERENCES users(id, org_id),\n  FOREIGN KEY (project_id, user_id) REFERENCES assignments(project_id, user_id) ON DELETE CASCADE\n);\n\nCREATE TABLE project_tags (\n  id      uuid PRIMARY KEY,\n  org_id  uuid NOT NULL REFERENCES organizations(id),\n  name    text NOT NULL CHECK (char_length(btrim(name)) BETWEEN 1 AND 50),\n  UNIQUE (id, org_id)\n);\n\nCREATE UNIQUE INDEX project_tags_name_idx ON project_tags (org_id, lower(btrim(name)));\n\nCREATE TABLE project_tag_links (\n  id         uuid PRIMARY KEY,\n  org_id     uuid NOT NULL REFERENCES organizations(id),\n  project_id uuid NOT NULL,\n  tag_id     uuid NOT NULL,\n  UNIQUE (project_id, tag_id),\n  FOREIGN KEY (project_id, org_id) REFERENCES projects(id, org_id) ON DELETE CASCADE,\n  FOREIGN KEY (tag_id, org_id) REFERENCES project_tags(id, org_id)\n);\n\nCREATE TABLE project_task_settings (\n  id           uuid PRIMARY KEY,\n  org_id       uuid NOT NULL REFERENCES organizations(id),\n  project_id   uuid NOT NULL,\n  task_id      uuid NOT NULL,\n  restricted   boolean NOT NULL DEFAULT false,\n  budget_minutes bigint CHECK (budget_minutes >= 0),\n  budget_cents bigint CHECK (budget_cents >= 0),\n  UNIQUE (project_id, task_id),\n  FOREIGN KEY (project_id, org_id) REFERENCES projects(id, org_id) ON DELETE CASCADE,\n  FOREIGN KEY (task_id, org_id) REFERENCES tasks(id, org_id),\n  FOREIGN KEY (project_id, task_id) REFERENCES project_tasks(project_id, task_id) ON DELETE CASCADE,\n  CHECK (budget_minutes IS NULL OR budget_cents IS NULL)\n);\n\nCREATE TABLE project_task_members (\n  id         uuid PRIMARY KEY,\n  org_id     uuid NOT NULL REFERENCES organizations(id),\n  project_id uuid NOT NULL,\n  task_id    uuid NOT NULL,\n  user_id    uuid NOT NULL,\n  UNIQUE (project_id, task_id, user_id),\n  FOREIGN KEY (project_id, org_id) REFERENCES projects(id, org_id) ON DELETE CASCADE,\n  FOREIGN KEY (task_id, org_id) REFERENCES tasks(id, org_id),\n  FOREIGN KEY (user_id, org_id) REFERENCES users(id, org_id),\n  FOREIGN KEY (project_id, task_id) REFERENCES project_task_settings(project_id, task_id) ON DELETE CASCADE,\n  FOREIGN KEY (project_id, user_id) REFERENCES assignments(project_id, user_id) ON DELETE CASCADE\n);\n\nCREATE TABLE project_member_budgets (\n  id             uuid PRIMARY KEY,\n  org_id         uuid NOT NULL REFERENCES organizations(id),\n  project_id     uuid NOT NULL,\n  user_id        uuid NOT NULL,\n  budget_minutes bigint NOT NULL CHECK (budget_minutes >= 0),\n  UNIQUE (project_id, user_id),\n  FOREIGN KEY (project_id, org_id) REFERENCES projects(id, org_id) ON DELETE CASCADE,\n  FOREIGN KEY (user_id, org_id) REFERENCES users(id, org_id),\n  FOREIGN KEY (project_id, user_id) REFERENCES assignments(project_id, user_id) ON DELETE CASCADE\n);\n\nCREATE TABLE project_fee_milestones (\n  id           uuid PRIMARY KEY,\n  org_id       uuid NOT NULL REFERENCES organizations(id),\n  project_id   uuid NOT NULL,\n  name         text NOT NULL CHECK (char_length(btrim(name)) BETWEEN 1 AND 200),\n  due_on       date NOT NULL,\n  amount_cents bigint NOT NULL CHECK (amount_cents >= 0),\n  position     smallint NOT NULL CHECK (position BETWEEN 0 AND 99),\n  UNIQUE (project_id, position),\n  UNIQUE (id, org_id),\n  FOREIGN KEY (project_id, org_id) REFERENCES projects(id, org_id) ON DELETE CASCADE\n);\n\nREVOKE ALL ON project_drafts, project_settings, project_private_settings,\n  project_member_costs, project_tags, project_tag_links, project_task_settings,\n  project_task_members, project_member_budgets, project_fee_milestones FROM PUBLIC;\n\n" rows_affected=0 rows_returned=0 elapsed=3.036002607s elapsed_secs=3.036002607 slow_threshold=1s
vm-test-run-horae-e2e-oidc> server # [  341.889614] horae[856]: 2026-11-03T11:16:56.877768Z  WARN sqlx::query: slow statement: execution time exceeded alert threshold summary="-- Invoice lines are …" db.statement="\n\n-- Invoice lines are the fee ledger; invoice status determines whether they count.\nALTER TABLE invoice_line_items\n  ADD COLUMN allocated_discount_cents bigint NOT NULL DEFAULT 0,\n  ADD COLUMN net_before_tax_cents bigint GENERATED ALWAYS AS\n    (amount_cents - allocated_discount_cents) STORED,\n  ADD CONSTRAINT invoice_line_discount_bounds CHECK\n    (allocated_discount_cents BETWEEN 0 AND amount_cents);\n\n-- Match core's largest-remainder allocation without rewriting gross amounts,\n-- headers or source identities. Stable source order breaks equal remainders.\nWITH source AS (\n  SELECT l.id, l.invoice_id, l.time_entry_id, f.project_id, f.period_key,\n         l.amount_cents::numeric AS gross, i.discount_cents::numeric AS discount,\n         sum(l.amount_cents::numeric) OVER (PARTITION BY l.invoice_id) AS subtotal\n  FROM invoice_line_items l\n  JOIN invoices i ON i.id = l.invoice_id\n  LEFT JOIN project_fee_occurrences f ON f.id = l.fee_occurrence_id\n), shares AS (\n  SELECT *, CASE WHEN subtotal = 0 THEN 0 ELSE floor(gross * discount / subtotal) END AS share,\n            CASE WHEN subtotal = 0 THEN 0 ELSE mod(gross * discount, subtotal) END AS remainder\n  FROM source\n), ranked AS (\n  SELECT *, discount - sum(share) OVER (PARTITION BY invoice_id) AS residual,\n         row_number() OVER (PARTITION BY invoice_id ORDER BY remainder DESC,\n           time_entry_id NULLS LAST, project_id, period_key COLLATE \"C\", id) AS position\n  FROM shares\n)\nUPDATE invoice_line_items l\nSET allocated_discount_cents = (r.share + CASE WHEN r.position <= r.residual THEN 1 ELSE 0 END)::bigint\nFROM ranked r WHERE r.id = l.id;\n\nCREATE INDEX invoice_lines_fee_balance ON invoice_line_items (fee_occurrence_id, invoice_id)\n  WHERE fee_occurrence_id IS NOT NULL;\nALTER TABLE project_fee_occurrences DROP COLUMN invoice_id;\n\nCREATE TABLE invoice_generation_requests (\n  id uuid PRIMARY KEY,\n  org_id uuid NOT NULL REFERENCES organizations(id),\n  actor_id uuid NOT NULL,\n  invoice_id uuid NOT NULL,\n  payload jsonb NOT NULL CHECK (jsonb_typeof(payload) = 'object' AND octet_length(payload::text) <= 262144),\n  created_at timestamptz NOT NULL DEFAULT now(),\n  FOREIGN KEY (actor_id, org_id) REFERENCES users(id, org_id),\n  FOREIGN KEY (invoice_id, org_id) REFERENCES invoices(id, org_id)\n);\nREVOKE ALL ON invoice_generation_requests FROM PUBLIC;\n\n" rows_affected=0 rows_returned=0 elapsed=1.141119261s elapsed_secs=1.141119261 slow_threshold=1s
vm-test-run-horae-e2e-oidc> server # [  346.775304] horae[856]: 2026-11-03T11:17:01.744390Z  INFO horae: Migrations complete.
vm-test-run-horae-e2e-oidc> server # [  347.213770] systemd[1]: Started Horae time tracking server.
vm-test-run-horae-e2e-oidc> server # [  347.796823] systemd[1]: Reached target Multi-User System.
vm-test-run-horae-e2e-oidc> server # [  347.841485] systemd[1]: Startup finished in 7.932s (kernel) + 1min 25.280s (initrd) + 4min 14.622s (userspace) = 5min 47.834s.
vm-test-run-horae-e2e-oidc> server: (finished: waiting for unit horae.service, in 37.76 seconds)
vm-test-run-horae-e2e-oidc> server: waiting for TCP port 5556 on localhost
vm-test-run-horae-e2e-oidc> server # Connection to localhost (127.0.0.1) 5556 port [tcp/freeciv] succeeded!
vm-test-run-horae-e2e-oidc> server: (finished: waiting for TCP port 5556 on localhost, in 1.57 seconds)
vm-test-run-horae-e2e-oidc> server: waiting for TCP port 3000 on localhost
vm-test-run-horae-e2e-oidc> server # [  349.778232] horae[910]: 2026-11-03T11:17:04.800950Z  INFO horae: Starting Horae on 127.0.0.1:3000
vm-test-run-horae-e2e-oidc> server # [  350.281054] horae[910]: 2026-11-03T11:17:05.343916Z  INFO sqlx::postgres::notice: relation "_sqlx_migrations" already exists, skipping
vm-test-run-horae-e2e-oidc> server # [  350.991881] horae[910]: 2026-11-03T11:17:06.010436Z  INFO horae::plugin::registry: plugins directory does not exist: plugins
vm-test-run-horae-e2e-oidc> server # [  351.409203] horae[910]: 2026-11-03T11:17:06.470337Z  INFO dioxus_server::server: Registering: POST /api/approve_submissions13590059188800848654
vm-test-run-horae-e2e-oidc> server # [  351.436981] horae[910]: 2026-11-03T11:17:06.496101Z  INFO dioxus_server::server: Registering: POST /api/approve_submission13590059188800848654
vm-test-run-horae-e2e-oidc> server # [  351.439182] horae[910]: 2026-11-03T11:17:06.500831Z  INFO dioxus_server::server: Registering: POST /api/reject_submission13590059188800848654
vm-test-run-horae-e2e-oidc> server # [  351.453726] horae[910]: 2026-11-03T11:17:06.502127Z  INFO dioxus_server::server: Registering: POST /api/list_approvals13590059188800848654
vm-test-run-horae-e2e-oidc> server # [  351.465298] horae[910]: 2026-11-03T11:17:06.515796Z  INFO dioxus_server::server: Registering: POST /api/submit_week13590059188800848654
vm-test-run-horae-e2e-oidc> server # [  351.467435] horae[910]: 2026-11-03T11:17:06.516373Z  INFO dioxus_server::server: Registering: POST /api/list_project_budget_progress13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.486369] horae[910]: 2026-11-03T11:17:06.516988Z  INFO dioxus_server::server: Registering: POST /api/get_project_fee_balances13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.505250] horae[910]: 2026-11-03T11:17:06.517267Z  INFO dioxus_server::server: Registering: POST /api/list_tracking_projects13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.507497] horae[910]: 2026-11-03T11:17:06.517632Z  INFO dioxus_server::server: Registering: POST /api/get_project_overview13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.522096] horae[910]: 2026-11-03T11:17:06.517932Z  INFO dioxus_server::server: Registering: POST /api/set_projects_active13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.523888] horae[910]: 2026-11-03T11:17:06.518203Z  INFO dioxus_server::server: Registering: POST /api/list_tracking_tasks13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.538668] horae[910]: 2026-11-03T11:17:06.518433Z  INFO dioxus_server::server: Registering: POST /api/get_project_details13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.549962] horae[910]: 2026-11-03T11:17:06.530538Z  INFO dioxus_server::server: Registering: POST /api/set_project_active13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.552053] horae[910]: 2026-11-03T11:17:06.536528Z  INFO dioxus_server::server: Registering: POST /api/list_project_tasks13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.563106] horae[910]: 2026-11-03T11:17:06.536842Z  INFO dioxus_server::server: Registering: POST /api/list_project_spend13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.573891] horae[910]: 2026-11-03T11:17:06.537501Z  INFO dioxus_server::server: Registering: POST /api/list_project_tags13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.575529] horae[910]: 2026-11-03T11:17:06.537756Z  INFO dioxus_server::server: Registering: POST /api/link_project_task13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.593758] horae[910]: 2026-11-03T11:17:06.537966Z  INFO dioxus_server::server: Registering: POST /api/delete_assignment13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.609551] horae[910]: 2026-11-03T11:17:06.538192Z  INFO dioxus_server::server: Registering: POST /api/create_assignment13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.621133] horae[910]: 2026-11-03T11:17:06.538405Z  INFO dioxus_server::server: Registering: POST /api/list_assignments13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.622944] horae[910]: 2026-11-03T11:17:06.547659Z  INFO dioxus_server::server: Registering: POST /api/set_task_active13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.633608] horae[910]: 2026-11-03T11:17:06.548295Z  INFO dioxus_server::server: Registering: POST /api/list_projects13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.635455] horae[910]: 2026-11-03T11:17:06.548545Z  INFO dioxus_server::server: Registering: POST /api/update_task13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.650807] horae[910]: 2026-11-03T11:17:06.548756Z  INFO dioxus_server::server: Registering: POST /api/create_task13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.654104] horae[910]: 2026-11-03T11:17:06.549081Z  INFO dioxus_server::server: Registering: POST /api/list_tasks13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  351.670509] horae[910]: 2026-11-03T11:17:06.549312Z  INFO dioxus_server::server: Registering: POST /api/update_invoice_status2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  351.677935] horae[910]: 2026-11-03T11:17:06.549701Z  INFO dioxus_server::server: Registering: POST /api/review_invoice_edit2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  351.679620] horae[910]: 2026-11-03T11:17:06.549911Z  INFO dioxus_server::server: Registering: POST /api/save_invoice_draft2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  351.697497] horae[910]: 2026-11-03T11:17:06.550142Z  INFO dioxus_server::server: Registering: POST /api/get_invoice_editor2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  351.699494] horae[910]: 2026-11-03T11:17:06.563688Z  INFO dioxus_server::server: Registering: POST /api/generate_invoice2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  351.718024] horae[910]: 2026-11-03T11:17:06.564251Z  INFO dioxus_server::server: Registering: POST /api/prepare_invoice2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  351.733777] horae[910]: 2026-11-03T11:17:06.564508Z  INFO dioxus_server::server: Registering: POST /api/list_invoices2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  351.735986] horae[910]: 2026-11-03T11:17:06.564798Z  INFO dioxus_server::server: Registering: POST /api/get_invoice2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  351.747666] horae[910]: 2026-11-03T11:17:06.565103Z  INFO dioxus_server::server: Registering: POST /api/list_plugins15265546378964521800
vm-test-run-horae-e2e-oidc> server # [  351.762348] horae[910]: 2026-11-03T11:17:06.565449Z  INFO dioxus_server::server: Registering: POST /api/preview_permission_template_deletion11579710309346027303
vm-test-run-horae-e2e-oidc> server # [  351.774102] horae[910]: 2026-11-03T11:17:06.565662Z  INFO dioxus_server::server: Registering: POST /api/preview_person_permissions11579710309346027303
vm-test-run-horae-e2e-oidc> server # [  351.789220] horae[910]: 2026-11-03T11:17:06.565852Z  INFO dioxus_server::server: Registering: POST /api/save_permission_template11579710309346027303
vm-test-run-horae-e2e-oidc> server # [  351.791629] horae[910]: 2026-11-03T11:17:06.566042Z  INFO dioxus_server::server: Registering: POST /api/list_permission_subjects11579710309346027303
vm-test-run-horae-e2e-oidc> server # [  351.811270] horae[910]: 2026-11-03T11:17:06.566263Z  INFO dioxus_server::server: Registering: POST /api/save_person_permissions11579710309346027303
vm-test-run-horae-e2e-oidc> server # [  351.827957] horae[910]: 2026-11-03T11:17:06.566448Z  INFO dioxus_server::server: Registering: POST /api/load_permission_editor11579710309346027303
vm-test-run-horae-e2e-oidc> server # [  351.838750] horae[910]: 2026-11-03T11:17:06.577853Z  INFO dioxus_server::server: Registering: POST /api/project_creation_selection1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  351.857428] horae[910]: 2026-11-03T11:17:06.578310Z  INFO dioxus_server::server: Registering: POST /api/project_creation_options1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  351.859167] horae[910]: 2026-11-03T11:17:06.595823Z  INFO dioxus_server::server: Registering: POST /api/project_creation_client1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  351.869796] horae[910]: 2026-11-03T11:17:06.596415Z  INFO dioxus_server::server: Registering: POST /api/project_editor_catalog1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  351.871773] horae[910]: 2026-11-03T11:17:06.596664Z  INFO dioxus_server::server: Registering: POST /api/finalize_project_draft1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  351.886885] horae[910]: 2026-11-03T11:17:06.596841Z  INFO dioxus_server::server: Registering: POST /api/discard_project_draft1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  351.902221] horae[910]: 2026-11-03T11:17:06.597303Z  INFO dioxus_server::server: Registering: POST /api/save_project_editor1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  351.904044] horae[910]: 2026-11-03T11:17:06.597550Z  INFO dioxus_server::server: Registering: POST /api/load_project_editor1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  351.919416] horae[910]: 2026-11-03T11:17:06.597824Z  INFO dioxus_server::server: Registering: POST /api/save_project_draft1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  351.938214] horae[910]: 2026-11-03T11:17:06.598067Z  INFO dioxus_server::server: Registering: POST /api/load_project_draft1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  351.940509] horae[910]: 2026-11-03T11:17:06.598383Z  INFO dioxus_server::server: Registering: POST /api/project_people1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  352.015153] horae[910]: 2026-11-03T11:17:06.608249Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/connection
vm-test-run-horae-e2e-oidc> server # [  352.029738] horae[910]: 2026-11-03T11:17:06.608729Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/cancel
vm-test-run-horae-e2e-oidc> server # [  352.031932] horae[910]: 2026-11-03T11:17:06.608960Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/csv-job/{mode}
vm-test-run-horae-e2e-oidc> server # [  352.065038] horae[910]: 2026-11-03T11:17:06.610081Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/start
vm-test-run-horae-e2e-oidc> server # [  352.067375] horae[910]: 2026-11-03T11:17:06.610340Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/retry
vm-test-run-horae-e2e-oidc> server # [  352.094350] horae[910]: 2026-11-03T11:17:06.619560Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/history
vm-test-run-horae-e2e-oidc> server # [  352.109213] horae[910]: 2026-11-03T11:17:06.621004Z  INFO dioxus_server::server: Registering: POST /api/harvest_change_account1479223498380199393
vm-test-run-horae-e2e-oidc> server # [  352.111674] horae[910]: 2026-11-03T11:17:06.621290Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/status
vm-test-run-horae-e2e-oidc> server # [  352.134789] horae[910]: 2026-11-03T11:17:06.621498Z  INFO dioxus_server::server: Registering: POST /api/harvest_connect_start1479223498380199393
vm-test-run-horae-e2e-oidc> server # [  352.146294] horae[910]: 2026-11-03T11:17:06.621697Z  INFO dioxus_server::server: Registering: POST /api/harvest_disconnect1479223498380199393
vm-test-run-horae-e2e-oidc> server # [  352.167342] horae[910]: 2026-11-03T11:17:06.621910Z  INFO dioxus_server::server: Registering: POST /api/load_task_catalog12256377810986817472
vm-test-run-horae-e2e-oidc> server # [  352.185620] horae[910]: 2026-11-03T11:17:06.622111Z  INFO dioxus_server::server: Registering: POST /api/update_client_profile10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  352.203923] horae[910]: 2026-11-03T11:17:06.622345Z  INFO dioxus_server::server: Registering: POST /api/create_project_client10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  352.210503] horae[910]: 2026-11-03T11:17:06.622520Z  INFO dioxus_server::server: Registering: POST /api/create_client_profile10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  352.246611] horae[910]: 2026-11-03T11:17:06.631778Z  INFO dioxus_server::server: Registering: POST /api/list_client_invoices10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  352.265600] horae[910]: 2026-11-03T11:17:06.632275Z  INFO dioxus_server::server: Registering: POST /api/get_client_details10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  352.267491] horae[910]: 2026-11-03T11:17:06.632479Z  INFO dioxus_server::server: Registering: POST /api/client_detail_view10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  352.289845] horae[910]: 2026-11-03T11:17:06.632672Z  INFO dioxus_server::server: Registering: POST /api/set_client_active10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  352.291463] horae[910]: 2026-11-03T11:17:06.632838Z  INFO dioxus_server::server: Registering: POST /api/client_overview10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  352.309713] horae[910]: 2026-11-03T11:17:06.633021Z  INFO dioxus_server::server: Registering: POST /api/update_client10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  352.311572] horae[910]: 2026-11-03T11:17:06.633237Z  INFO dioxus_server::server: Registering: POST /api/create_client10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  352.333349] horae[910]: 2026-11-03T11:17:06.633462Z  INFO dioxus_server::server: Registering: POST /api/list_clients10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  352.335452] horae[910]: 2026-11-03T11:17:06.633793Z  INFO dioxus_server::server: Registering: POST /api/get_project_detail_view7931148123265998511
vm-test-run-horae-e2e-oidc> server # [  352.357959] horae[910]: 2026-11-03T11:17:06.634095Z  INFO dioxus_server::server: Registering: POST /api/list_visible_time_report_entries7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  352.370187] horae[910]: 2026-11-03T11:17:06.634400Z  INFO dioxus_server::server: Registering: POST /api/list_visible_time_report_groups7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  352.377523] horae[910]: 2026-11-03T11:17:06.643924Z  INFO dioxus_server::server: Registering: POST /api/get_time_report_access7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  352.379361] horae[910]: 2026-11-03T11:17:06.644615Z  INFO dioxus_server::server: Registering: POST /api/get_plugin_widgets7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  352.403628] horae[910]: 2026-11-03T11:17:06.644925Z  INFO dioxus_server::server: Registering: POST /api/report_detailed7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  352.414199] horae[910]: 2026-11-03T11:17:06.645152Z  INFO dioxus_server::server: Registering: POST /api/report_time7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  352.435349] horae[910]: 2026-11-03T11:17:06.645359Z  INFO dioxus_server::server: Registering: POST /api/set_user_active13739675588719463496
vm-test-run-horae-e2e-oidc> server # [  352.448602] horae[910]: 2026-11-03T11:17:06.645556Z  INFO dioxus_server::server: Registering: POST /api/set_user_role13739675588719463496
vm-test-run-horae-e2e-oidc> server # [  352.450723] horae[910]: 2026-11-03T11:17:06.645813Z  INFO dioxus_server::server: Registering: POST /api/list_people13739675588719463496
vm-test-run-horae-e2e-oidc> server # [  352.457663] horae[910]: 2026-11-03T11:17:06.646030Z  INFO dioxus_server::server: Registering: POST /api/create_user13739675588719463496
vm-test-run-horae-e2e-oidc> server # [  352.459617] horae[910]: 2026-11-03T11:17:06.646245Z  INFO dioxus_server::server: Registering: POST /api/list_users13739675588719463496
vm-test-run-horae-e2e-oidc> server # [  352.475980] horae[910]: 2026-11-03T11:17:06.646524Z  INFO dioxus_server::server: Registering: POST /api/save_project_managers11474746963446121934
vm-test-run-horae-e2e-oidc> server # [  352.505697] horae[910]: 2026-11-03T11:17:06.655935Z  INFO dioxus_server::server: Registering: POST /api/load_project_managers11474746963446121934
vm-test-run-horae-e2e-oidc> server # [  352.507964] horae[910]: 2026-11-03T11:17:06.656212Z  INFO dioxus_server::server: Registering: POST /api/list_visible_time_entries16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.514755] horae[910]: 2026-11-03T11:17:06.656457Z  INFO dioxus_server::server: Registering: POST /api/list_time_entry_contexts16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.524959] horae[910]: 2026-11-03T11:17:06.656649Z  INFO dioxus_server::server: Registering: POST /api/reorder_untimed_entries16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.527362] horae[910]: 2026-11-03T11:17:06.656832Z  INFO dioxus_server::server: Registering: POST /api/load_timesheet_tracking16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.558872] horae[910]: 2026-11-03T11:17:06.657045Z  INFO dioxus_server::server: Registering: POST /api/apply_timesheet_command16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.570229] horae[910]: 2026-11-03T11:17:06.657303Z  INFO dioxus_server::server: Registering: POST /api/reschedule_time_entry16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.571886] horae[910]: 2026-11-03T11:17:06.657863Z  INFO dioxus_server::server: Registering: POST /api/list_timesheet_people16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.582657] horae[910]: 2026-11-03T11:17:06.658111Z  INFO dioxus_server::server: Registering: POST /api/load_timesheet_page16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.593497] horae[910]: 2026-11-03T11:17:06.658332Z  INFO dioxus_server::server: Registering: POST /api/update_time_entry16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.596187] horae[910]: 2026-11-03T11:17:06.658521Z  INFO dioxus_server::server: Registering: POST /api/list_time_entries16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.624906] horae[910]: 2026-11-03T11:17:06.670254Z  INFO dioxus_server::server: Registering: POST /api/get_current_timer16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.627071] horae[910]: 2026-11-03T11:17:06.673297Z  INFO dioxus_server::server: Registering: POST /api/delete_time_entry16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.647096] horae[910]: 2026-11-03T11:17:06.673934Z  INFO dioxus_server::server: Registering: POST /api/create_time_entry16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.662179] horae[910]: 2026-11-03T11:17:06.674205Z  INFO dioxus_server::server: Registering: POST /api/start_timer16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.663713] horae[910]: 2026-11-03T11:17:06.674445Z  INFO dioxus_server::server: Registering: POST /api/stop_timer16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  352.682702] horae[910]: 2026-11-03T11:17:06.683546Z  INFO dioxus_server::server: Registering: POST /api/update_org_branding13047172052397277026
vm-test-run-horae-e2e-oidc> server # [  352.693581] horae[910]: 2026-11-03T11:17:06.683973Z  INFO dioxus_server::server: Registering: POST /api/get_org_branding13047172052397277026
vm-test-run-horae-e2e-oidc> server # [  352.705019] horae[910]: 2026-11-03T11:17:06.684372Z  INFO dioxus_server::server: Registering: POST /api/get_week_start13047172052397277026
vm-test-run-horae-e2e-oidc> server # [  352.707215] horae[910]: 2026-11-03T11:17:06.684601Z  INFO dioxus_server::server: Registering: POST /api/get_org_name13047172052397277026
vm-test-run-horae-e2e-oidc> server # [  352.725529] horae[910]: 2026-11-03T11:17:06.684799Z  INFO dioxus_server::server: Registering: POST /api/logout16144359270796124307
vm-test-run-horae-e2e-oidc> server # [  352.727484] horae[910]: 2026-11-03T11:17:06.685024Z  INFO dioxus_server::server: Registering: POST /api/get_me16144359270796124307
vm-test-run-horae-e2e-oidc> server # [  352.741494] horae[910]: 2026-11-03T11:17:06.685226Z  INFO dioxus_server::server: Registering: POST /api/list_permission_audit16144359270796124307
vm-test-run-horae-e2e-oidc> server # [  352.742974] horae[910]: 2026-11-03T11:17:06.685488Z  INFO dioxus_server::server: Registering: POST /api/get_permission_audit16144359270796124307
vm-test-run-horae-e2e-oidc> server # [  352.760800] horae[910]: 2026-11-03T11:17:06.685709Z  INFO dioxus_server::server: Registering: POST /api/get_my_permissions16144359270796124307
vm-test-run-horae-e2e-oidc> server # [  352.762717] horae[910]: 2026-11-03T11:17:07.073315Z  INFO horae: Listening on 127.0.0.1:3000
vm-test-run-horae-e2e-oidc> server # Connection to localhost (127.0.0.1) 3000 port [tcp/hbci] succeeded!
vm-test-run-horae-e2e-oidc> server: (finished: waiting for TCP port 3000 on localhost, in 3.66 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: curl -sf http://127.0.0.1:3000/health | grep -q ok
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: curl -sf http://127.0.0.1:3000/health | grep -q ok, in 1.38 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: curl -sf http://127.0.0.1:5556/dex/.well-known/openid-configuration >/dev/null
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: curl -sf http://127.0.0.1:5556/dex/.well-known/openid-configuration >/dev/null, in 1.05 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: sudo -u horae DATABASE_URL=postgres:///horae horae seed
vm-test-run-horae-e2e-oidc> server # [  356.911303] sudo[940]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; ENV=DATABASE_URL=postgres:///horae ; COMMAND=/run/current-system/sw/bin/horae seed
vm-test-run-horae-e2e-oidc> server # [  358.082875] sudo[940]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  360.762801] postgres[947]: [947] LOG:  could not receive data from client: Connection reset by peer
vm-test-run-horae-e2e-oidc> server # [  360.907022] sudo[940]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: sudo -u horae DATABASE_URL=postgres:///horae horae seed, in 5.26 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: sudo -u horae DATABASE_URL=postgres:///horae horae user create --email kilgore@kilgore.trout --name 'Kilgore Trout' --role member
vm-test-run-horae-e2e-oidc> server # [  361.851895] sudo[948]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; ENV=DATABASE_URL=postgres:///horae ; COMMAND=/run/current-system/sw/bin/horae user create --email kilgore@kilgore.trout --name 'Kilgore Trout' --role member
vm-test-run-horae-e2e-oidc> server # [  362.874212] sudo[948]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  363.703599] postgres[955]: [955] LOG:  could not receive data from client: Connection reset by peer
vm-test-run-horae-e2e-oidc> server # [  363.765346] sudo[948]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: sudo -u horae DATABASE_URL=postgres:///horae horae user create --email kilgore@kilgore.trout --name 'Kilgore Trout' --role member, in 2.89 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: curl -s -c /tmp/jar.txt -b /tmp/jar.txt -L http://127.0.0.1:3000/auth/oidc/start -o /dev/null
vm-test-run-horae-e2e-oidc> server # [  365.793231] dex[655]: time=2026-11-03T11:17:20.786Z level=INFO msg="login successful" connector_id=mock username="Kilgore Trout" preferred_username="" email=kilgore@kilgore.trout groups=[authors] request_id=686677f7-b25f-42c9-8adf-de0e310b4677
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: curl -s -c /tmp/jar.txt -b /tmp/jar.txt -L http://127.0.0.1:3000/auth/oidc/start -o /dev/null, in 4.31 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: curl -s -b /tmp/jar.txt http://127.0.0.1:3000/harvest/v2/time_entries
vm-test-run-horae-e2e-oidc> server # [  371.171425] horae[910]: 2026-11-03T11:17:26.196800Z  WARN call: sqlx::query: slow statement: execution time exceeded alert threshold summary="SELECT te.id, te.spent_date as …" db.statement="\n\nSELECT te.id,\n               te.spent_date as \"spent_date: chrono::NaiveDate\",\n               te.minutes, te.start_minute, te.rounded_minutes, te.notes,\n               (te.billable AND (te.invoice_id IS NOT NULL OR (p.project_type <> 'non_billable' AND COALESCE(pt.billable, t.billable_default)))) as \"billable!\", te.is_running,\n               te.started_at as \"started_at: chrono::DateTime<chrono::Utc>\",\n               te.state::text AS \"state!: String\", te.invoice_id,\n               te.created_at as \"created_at: chrono::DateTime<chrono::Utc>\",\n               te.updated_at as \"updated_at: chrono::DateTime<chrono::Utc>\",\n               te.user_id, u.name AS user_name,\n               te.project_id, p.name AS project_name, p.code AS project_code,\n               te.task_id, t.name AS task_name,\n               p.client_id, c.name AS client_name,\n               CASE WHEN viewer.org_role IN ('admin', 'manager') THEN COALESCE(line.rate_cents,\n                 CASE WHEN ps.project_id IS NULL OR p.project_type = 'time_and_materials'\n                 THEN resolve_project_rate(ps.rate_mode, pt.rate_cents, a.rate_cents, p.rate_cents,\n                 CASE WHEN ps.project_id IS NULL OR p.currency = o.default_currency THEN u.billable_rate_cents END,\n                 CASE WHEN p.currency = c.currency THEN c.default_rate_cents END\n               ) END) END AS \"billable_rate_cents?\",\n               CASE WHEN viewer.org_role = 'admin' OR (viewer.org_role = 'manager' AND mc.id IS NULL)\n                 THEN COALESCE(mc.cost_rate_cents, u.cost_rate_cents) END AS user_cost_rate_cents,\n               CASE WHEN access.can_view_progress THEN p.budget_kind::text END AS \"budget_kind?: String\"\n         FROM time_entries te\n         JOIN users viewer ON viewer.id = $10 AND viewer.org_id = te.org_id AND viewer.active\n         JOIN users u ON u.id = te.user_id\n         JOIN projects p ON p.id = te.project_id\n         LEFT JOIN project_read_access access ON access.project_id = p.id AND access.org_id = p.org_id AND access.user_id = viewer.id\n         JOIN tasks t ON t.id = te.task_id\n         LEFT JOIN project_tasks pt ON pt.project_id = te.project_id AND pt.task_id = te.task_id\n         LEFT JOIN assignments a ON a.project_id = te.project_id AND a.user_id = te.user_id\n         LEFT JOIN invoice_line_items line ON line.invoice_id = te.invoice_id AND line.time_entry_id = te.id\n         JOIN clients c ON c.id = p.client_id\n         JOIN organizations o ON o.id = te.org_id\n         LEFT JOIN project_settings ps ON ps.project_id = p.id\n         LEFT JOIN project_member_costs mc ON mc.project_id = te.project_id AND mc.user_id = te.user_id\n         WHERE te.org_id = $1 AND (viewer.org_role IN ('admin', 'manager') OR te.user_id = viewer.id)\n           AND ($2::uuid IS NULL OR te.user_id = $2)\n           AND ($3::uuid IS NULL OR te.project_id = $3)\n           AND ($4::date IS NULL OR te.spent_date >= $4::date)\n           AND ($5::date IS NULL OR te.spent_date <= $5::date)\n           AND ($6::bool IS NULL OR te.is_running = $6)\n           AND ($7::timestamptz IS NULL OR te.updated_at >= $7::timestamptz)\n         ORDER BY te.spent_date DESC, te.created_at DESC, te.id DESC\n         LIMIT $8 OFFSET $9\n" rows_affected=0 rows_returned=0 elapsed=1.608674743s elapsed_secs=1.608674743 slow_threshold=1s
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: curl -s -b /tmp/jar.txt http://127.0.0.1:3000/harvest/v2/time_entries, in 3.11 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: sudo -u horae psql horae -tAc 'SELECT id FROM users WHERE email = '"'"'kilgore@kilgore.trout'"'"''
vm-test-run-horae-e2e-oidc> server # [  372.191832] sudo[965]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; COMMAND=/run/current-system/sw/bin/psql horae -tAc 'SELECT id FROM users WHERE email = \'kilgore@kilgore.trout\''
vm-test-run-horae-e2e-oidc> server # [  373.445857] sudo[965]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  374.146774] sudo[965]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: sudo -u horae psql horae -tAc 'SELECT id FROM users WHERE email = '"'"'kilgore@kilgore.trout'"'"'', in 2.97 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: dex-id-token horae horae-e2e-secret
vm-test-run-horae-e2e-oidc> server # [  393.822987] dex[655]: time=2026-11-03T11:17:48.837Z level=INFO msg="login successful" connector_id=mock username="Kilgore Trout" preferred_username="" email=kilgore@kilgore.trout groups=[authors] request_id=9ac16348-35e4-411d-8ba3-3c6a354a4b89
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: dex-id-token horae horae-e2e-secret, in 21.08 seconds)
vm-test-run-horae-e2e-oidc> server # [  396.482861] sudo[981]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; COMMAND=/run/current-system/sw/bin/env DATABASE_URL=postgres:///horae HORAE_OIDC_ISSUER=http://127.0.0.1:5556/dex horae user link-oidc --user-id 01a1a120-b834-74c0-85e1-f4aab2453f38 --issuer http://127.0.0.1:5556/dex --subject Cg0wLTM4NS0yODA4OS0wEgRtb2Nr
vm-test-run-horae-e2e-oidc> server # [  397.563555] sudo[981]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  398.511515] postgres[986]: [986] LOG:  could not receive data from client: Connection reset by peer
vm-test-run-horae-e2e-oidc> server # [  398.613625] sudo[981]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server: must succeed: sudo -u horae psql horae -c "UPDATE users SET active = false WHERE email = 'kilgore@kilgore.trout'"
vm-test-run-horae-e2e-oidc> server # [  399.519826] sudo[987]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; COMMAND=/run/current-system/sw/bin/psql horae -c 'UPDATE users SET active = false WHERE email = \'kilgore@kilgore.trout\''
vm-test-run-horae-e2e-oidc> server # [  400.615432] sudo[987]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  401.306951] sudo[987]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: sudo -u horae psql horae -c "UPDATE users SET active = false WHERE email = 'kilgore@kilgore.trout'", in 2.72 seconds)
vm-test-run-horae-e2e-oidc> server # [  402.779080] dex[655]: time=2026-11-03T11:17:57.809Z level=INFO msg="login successful" connector_id=mock username="Kilgore Trout" preferred_username="" email=kilgore@kilgore.trout groups=[authors] request_id=1e4303dc-6907-413e-802f-ac95cf8d3f2d
vm-test-run-horae-e2e-oidc> server # [  403.257449] horae[910]: 2026-11-03T11:17:58.276192Z  WARN call: horae::auth::oidc: OIDC login denied: account is deactivated
vm-test-run-horae-e2e-oidc> server: must succeed: curl -s -o /dev/null -w '%{http_code}' -b /tmp/jar2.txt http://127.0.0.1:3000/harvest/v2/time_entries
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: curl -s -o /dev/null -w '%{http_code}' -b /tmp/jar2.txt http://127.0.0.1:3000/harvest/v2/time_entries, in 0.95 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: sudo -u horae psql horae -tAc 'UPDATE users SET active = true, oidc_issuer = NULL, oidc_subject = NULL WHERE email = '"'"'kilgore@kilgore.trout'"'"''
vm-test-run-horae-e2e-oidc> server # [  405.303887] sudo[1002]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; COMMAND=/run/current-system/sw/bin/psql horae -tAc 'UPDATE users SET active = true, oidc_issuer = NULL, oidc_subject = NULL WHERE email = \'kilgore@kilgore.trout\''
vm-test-run-horae-e2e-oidc> server # [  406.670700] sudo[1002]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  407.410167] sudo[1002]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: sudo -u horae psql horae -tAc 'UPDATE users SET active = true, oidc_issuer = NULL, oidc_subject = NULL WHERE email = '"'"'kilgore@kilgore.trout'"'"'', in 3.14 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: mkdir -p /run/systemd/system/horae.service.d && printf '%s\n' '[Service]' 'Environment=HORAE_OIDC_CLIENT_ID=horae-omit-email-verified' 'Environment=HORAE_OIDC_CLIENT_SECRET=horae-omit-e2e-secret' > /run/systemd/system/horae.service.d/omit-email-verified.conf
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: mkdir -p /run/systemd/system/horae.service.d && printf '%s\n' '[Service]' 'Environment=HORAE_OIDC_CLIENT_ID=horae-omit-email-verified' 'Environment=HORAE_OIDC_CLIENT_SECRET=horae-omit-e2e-secret' > /run/systemd/system/horae.service.d/omit-email-verified.conf, in 0.58 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: systemctl daemon-reload && systemctl restart horae.service
vm-test-run-horae-e2e-oidc> server # [  408.821659] systemd[1]: Reload requested from client PID 1017 ('systemctl') (unit backdoor.service)...
vm-test-run-horae-e2e-oidc> server # [  408.835849] systemd[1]: Reloading...
vm-test-run-horae-e2e-oidc> server # [  429.555361] systemd[1]: Reloading finished in 20672 ms.
vm-test-run-horae-e2e-oidc> server # [  432.699245] systemd[1]: Stopping Horae time tracking server...
vm-test-run-horae-e2e-oidc> server # [  433.049954] systemd[1]: horae.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [  433.115476] systemd[1]: Stopped Horae time tracking server.
vm-test-run-horae-e2e-oidc> server # [  433.149390] systemd[1]: horae.service: Consumed 4.100s CPU time over 1min 52.169s wall clock time, 84.4M memory peak, 78.7M read from disk, 17.1K incoming IP traffic, 23K outgoing IP traffic.
vm-test-run-horae-e2e-oidc> server # [  433.583993] systemd[1]: Starting Horae time tracking server...
vm-test-run-horae-e2e-oidc> server # [  435.767644] horae[1059]: 2026-11-03T11:18:30.792950Z  INFO horae: Running migrations...
vm-test-run-horae-e2e-oidc> server # [  435.813555] horae[1059]: 2026-11-03T11:18:30.877493Z  INFO sqlx::postgres::notice: relation "_sqlx_migrations" already exists, skipping
vm-test-run-horae-e2e-oidc> server # [  436.332490] horae[1059]: 2026-11-03T11:18:31.397946Z  INFO horae: Migrations complete.
vm-test-run-horae-e2e-oidc> server # [  436.403642] postgres[1063]: [1063] LOG:  could not receive data from client: Connection reset by peer
vm-test-run-horae-e2e-oidc> server # [  436.586154] systemd[1]: Started Horae time tracking server.
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: systemctl daemon-reload && systemctl restart horae.service, in 28.68 seconds)
vm-test-run-horae-e2e-oidc> server: waiting for TCP port 3000 on localhost
vm-test-run-horae-e2e-oidc> server # [  438.377577] horae[1066]: 2026-11-03T11:18:33.408230Z  INFO horae: Starting Horae on 127.0.0.1:3000
vm-test-run-horae-e2e-oidc> server # [  438.699957] horae[1066]: 2026-11-03T11:18:33.763924Z  INFO sqlx::postgres::notice: relation "_sqlx_migrations" already exists, skipping
vm-test-run-horae-e2e-oidc> server # [  439.455477] horae[1066]: 2026-11-03T11:18:34.468293Z  INFO horae::plugin::registry: plugins directory does not exist: plugins
vm-test-run-horae-e2e-oidc> server # [  439.478950] horae[1066]: 2026-11-03T11:18:34.532673Z  INFO sqlx::postgres::notice: schema "tower_sessions" already exists, skipping
vm-test-run-horae-e2e-oidc> server # [  439.502225] horae[1066]: 2026-11-03T11:18:34.555869Z  INFO sqlx::postgres::notice: relation "session" already exists, skipping
vm-test-run-horae-e2e-oidc> server # [  439.522173] horae[1066]: 2026-11-03T11:18:34.581933Z  INFO dioxus_server::server: Registering: POST /api/approve_submissions13590059188800848654
vm-test-run-horae-e2e-oidc> server # [  439.538388] horae[1066]: 2026-11-03T11:18:34.582485Z  INFO dioxus_server::server: Registering: POST /api/approve_submission13590059188800848654
vm-test-run-horae-e2e-oidc> server # [  439.558486] horae[1066]: 2026-11-03T11:18:34.596789Z  INFO dioxus_server::server: Registering: POST /api/reject_submission13590059188800848654
vm-test-run-horae-e2e-oidc> server # [  439.581617] horae[1066]: 2026-11-03T11:18:34.597359Z  INFO dioxus_server::server: Registering: POST /api/list_approvals13590059188800848654
vm-test-run-horae-e2e-oidc> server # [  439.583995] horae[1066]: 2026-11-03T11:18:34.597796Z  INFO dioxus_server::server: Registering: POST /api/submit_week13590059188800848654
vm-test-run-horae-e2e-oidc> server # [  439.607897] horae[1066]: 2026-11-03T11:18:34.598014Z  INFO dioxus_server::server: Registering: POST /api/list_project_budget_progress13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.623170] horae[1066]: 2026-11-03T11:18:34.598250Z  INFO dioxus_server::server: Registering: POST /api/get_project_fee_balances13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.638173] horae[1066]: 2026-11-03T11:18:34.598435Z  INFO dioxus_server::server: Registering: POST /api/list_tracking_projects13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.654237] horae[1066]: 2026-11-03T11:18:34.615503Z  INFO dioxus_server::server: Registering: POST /api/get_project_overview13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.672813] horae[1066]: 2026-11-03T11:18:34.615937Z  INFO dioxus_server::server: Registering: POST /api/set_projects_active13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.674895] horae[1066]: 2026-11-03T11:18:34.616195Z  INFO dioxus_server::server: Registering: POST /api/list_tracking_tasks13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.693782] horae[1066]: 2026-11-03T11:18:34.616400Z  INFO dioxus_server::server: Registering: POST /api/get_project_details13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.695484] horae[1066]: 2026-11-03T11:18:34.616555Z  INFO dioxus_server::server: Registering: POST /api/set_project_active13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.717715] horae[1066]: 2026-11-03T11:18:34.616738Z  INFO dioxus_server::server: Registering: POST /api/list_project_tasks13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.719485] horae[1066]: 2026-11-03T11:18:34.616961Z  INFO dioxus_server::server: Registering: POST /api/list_project_spend13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.750981] horae[1066]: 2026-11-03T11:18:34.617430Z  INFO dioxus_server::server: Registering: POST /api/list_project_tags13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.770875] horae[1066]: 2026-11-03T11:18:34.617636Z  INFO dioxus_server::server: Registering: POST /api/link_project_task13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.790074] horae[1066]: 2026-11-03T11:18:34.617811Z  INFO dioxus_server::server: Registering: POST /api/delete_assignment13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.804985] horae[1066]: 2026-11-03T11:18:34.617964Z  INFO dioxus_server::server: Registering: POST /api/create_assignment13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.807727] horae[1066]: 2026-11-03T11:18:34.618108Z  INFO dioxus_server::server: Registering: POST /api/list_assignments13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.834684] horae[1066]: 2026-11-03T11:18:34.618311Z  INFO dioxus_server::server: Registering: POST /api/set_task_active13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.849812] horae[1066]: 2026-11-03T11:18:34.618515Z  INFO dioxus_server::server: Registering: POST /api/list_projects13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.875125] horae[1066]: 2026-11-03T11:18:34.643538Z  INFO dioxus_server::server: Registering: POST /api/update_task13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.894266] horae[1066]: 2026-11-03T11:18:34.643984Z  INFO dioxus_server::server: Registering: POST /api/create_task13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.896128] horae[1066]: 2026-11-03T11:18:34.644236Z  INFO dioxus_server::server: Registering: POST /api/list_tasks13963200375258473206
vm-test-run-horae-e2e-oidc> server # [  439.926901] horae[1066]: 2026-11-03T11:18:34.644599Z  INFO dioxus_server::server: Registering: POST /api/update_invoice_status2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  439.958095] horae[1066]: 2026-11-03T11:18:34.644806Z  INFO dioxus_server::server: Registering: POST /api/review_invoice_edit2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  439.977012] horae[1066]: 2026-11-03T11:18:34.644968Z  INFO dioxus_server::server: Registering: POST /api/save_invoice_draft2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  439.996771] horae[1066]: 2026-11-03T11:18:34.645184Z  INFO dioxus_server::server: Registering: POST /api/get_invoice_editor2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  439.999606] horae[1066]: 2026-11-03T11:18:34.645840Z  INFO dioxus_server::server: Registering: POST /api/generate_invoice2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  440.018518] horae[1066]: 2026-11-03T11:18:34.646044Z  INFO dioxus_server::server: Registering: POST /api/prepare_invoice2064041990223864818
vm-test-run-horae-e2e-oidc> server # Connection to localhost (127.0.0.1) 3000 port [tcp/hbci] succeeded!
vm-test-run-horae-e2e-oidc> server # [  440.049166] horae[1066]: 2026-11-03T11:18:34.646243Z  INFO dioxus_server::server: Registering: POST /api/list_invoices2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  440.051649] horae[1066]: 2026-11-03T11:18:34.646393Z  INFO dioxus_server::server: Registering: POST /api/get_invoice2064041990223864818
vm-test-run-horae-e2e-oidc> server # [  440.074371] horae[1066]: 2026-11-03T11:18:34.676044Z  INFO dioxus_server::server: Registering: POST /api/list_plugins15265546378964521800
vm-test-run-horae-e2e-oidc> server # [  440.097765] horae[1066]: 2026-11-03T11:18:34.676665Z  INFO dioxus_server::server: Registering: POST /api/preview_permission_template_deletion11579710309346027303
vm-test-run-horae-e2e-oidc> server # [  440.130363] horae[1066]: 2026-11-03T11:18:34.676892Z  INFO dioxus_server::server: Registering: POST /api/preview_person_permissions11579710309346027303
vm-test-run-horae-e2e-oidc> server # [  440.141621] horae[1066]: 2026-11-03T11:18:34.677070Z  INFO dioxus_server::server: Registering: POST /api/save_permission_template11579710309346027303
vm-test-run-horae-e2e-oidc> server # [  440.143828] horae[1066]: 2026-11-03T11:18:34.677255Z  INFO dioxus_server::server: Registering: POST /api/list_permission_subjects11579710309346027303
vm-test-run-horae-e2e-oidc> server # [  440.194156] horae[1066]: 2026-11-03T11:18:34.677406Z  INFO dioxus_server::server: Registering: POST /api/save_person_permissions11579710309346027303
vm-test-run-horae-e2e-oidc> server # [  440.209396] horae[1066]: 2026-11-03T11:18:34.677577Z  INFO dioxus_server::server: Registering: POST /api/load_permission_editor11579710309346027303
vm-test-run-horae-e2e-oidc> server: (finished: waiting for TCP port 3000 on localhost, in 3.43 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: dex-id-token horae-omit-email-verified horae-omit-e2e-secret
vm-test-run-horae-e2e-oidc> server # [  440.212042] horae[1066]: 2026-11-03T11:18:34.677736Z  INFO dioxus_server::server: Registering: POST /api/project_creation_selection1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  440.261177] horae[1066]: 2026-11-03T11:18:34.677888Z  INFO dioxus_server::server: Registering: POST /api/project_creation_options1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  440.263451] horae[1066]: 2026-11-03T11:18:34.678036Z  INFO dioxus_server::server: Registering: POST /api/project_creation_client1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  440.290247] horae[1066]: 2026-11-03T11:18:34.678200Z  INFO dioxus_server::server: Registering: POST /api/project_editor_catalog1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  440.325785] horae[1066]: 2026-11-03T11:18:34.691268Z  INFO dioxus_server::server: Registering: POST /api/finalize_project_draft1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  440.345829] horae[1066]: 2026-11-03T11:18:34.691826Z  INFO dioxus_server::server: Registering: POST /api/discard_project_draft1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  440.373342] horae[1066]: 2026-11-03T11:18:34.692080Z  INFO dioxus_server::server: Registering: POST /api/save_project_editor1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  440.400704] horae[1066]: 2026-11-03T11:18:34.692311Z  INFO dioxus_server::server: Registering: POST /api/load_project_editor1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  440.403124] horae[1066]: 2026-11-03T11:18:34.692476Z  INFO dioxus_server::server: Registering: POST /api/save_project_draft1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  440.510953] horae[1066]: 2026-11-03T11:18:34.692641Z  INFO dioxus_server::server: Registering: POST /api/load_project_draft1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  440.529723] horae[1066]: 2026-11-03T11:18:34.692988Z  INFO dioxus_server::server: Registering: POST /api/project_people1604479113674082919
vm-test-run-horae-e2e-oidc> server # [  440.554142] horae[1066]: 2026-11-03T11:18:34.693233Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/connection
vm-test-run-horae-e2e-oidc> server # [  440.573488] horae[1066]: 2026-11-03T11:18:34.693417Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/cancel
vm-test-run-horae-e2e-oidc> server # [  440.575813] horae[1066]: 2026-11-03T11:18:34.693585Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/csv-job/{mode}
vm-test-run-horae-e2e-oidc> server # [  440.624832] horae[1066]: 2026-11-03T11:18:34.693778Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/start
vm-test-run-horae-e2e-oidc> server # [  440.627202] horae[1066]: 2026-11-03T11:18:34.693986Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/retry
vm-test-run-horae-e2e-oidc> server # [  440.649999] horae[1066]: 2026-11-03T11:18:34.694339Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/history
vm-test-run-horae-e2e-oidc> server # [  440.651706] horae[1066]: 2026-11-03T11:18:34.712736Z  INFO dioxus_server::server: Registering: POST /api/harvest_change_account1479223498380199393
vm-test-run-horae-e2e-oidc> server # [  440.678719] horae[1066]: 2026-11-03T11:18:34.713314Z  INFO dioxus_server::server: Registering: POST /api/import/harvest/status
vm-test-run-horae-e2e-oidc> server # [  440.698649] horae[1066]: 2026-11-03T11:18:34.713580Z  INFO dioxus_server::server: Registering: POST /api/harvest_connect_start1479223498380199393
vm-test-run-horae-e2e-oidc> server # [  440.713251] horae[1066]: 2026-11-03T11:18:34.713756Z  INFO dioxus_server::server: Registering: POST /api/harvest_disconnect1479223498380199393
vm-test-run-horae-e2e-oidc> server # [  440.716034] horae[1066]: 2026-11-03T11:18:34.713917Z  INFO dioxus_server::server: Registering: POST /api/load_task_catalog12256377810986817472
vm-test-run-horae-e2e-oidc> server # [  440.735108] horae[1066]: 2026-11-03T11:18:34.714069Z  INFO dioxus_server::server: Registering: POST /api/update_client_profile10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  440.754342] horae[1066]: 2026-11-03T11:18:34.714256Z  INFO dioxus_server::server: Registering: POST /api/create_project_client10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  440.755975] horae[1066]: 2026-11-03T11:18:34.714442Z  INFO dioxus_server::server: Registering: POST /api/create_client_profile10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  440.775186] horae[1066]: 2026-11-03T11:18:34.731559Z  INFO dioxus_server::server: Registering: POST /api/list_client_invoices10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  440.799324] horae[1066]: 2026-11-03T11:18:34.732314Z  INFO dioxus_server::server: Registering: POST /api/get_client_details10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  440.814463] horae[1066]: 2026-11-03T11:18:34.732518Z  INFO dioxus_server::server: Registering: POST /api/client_detail_view10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  440.833318] horae[1066]: 2026-11-03T11:18:34.732690Z  INFO dioxus_server::server: Registering: POST /api/set_client_active10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  440.835821] horae[1066]: 2026-11-03T11:18:34.732835Z  INFO dioxus_server::server: Registering: POST /api/client_overview10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  440.858497] horae[1066]: 2026-11-03T11:18:34.732996Z  INFO dioxus_server::server: Registering: POST /api/update_client10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  440.876970] horae[1066]: 2026-11-03T11:18:34.733185Z  INFO dioxus_server::server: Registering: POST /api/create_client10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  440.878878] horae[1066]: 2026-11-03T11:18:34.733353Z  INFO dioxus_server::server: Registering: POST /api/list_clients10485135825777491571
vm-test-run-horae-e2e-oidc> server # [  440.901089] horae[1066]: 2026-11-03T11:18:34.733656Z  INFO dioxus_server::server: Registering: POST /api/get_project_detail_view7931148123265998511
vm-test-run-horae-e2e-oidc> server # [  440.903129] horae[1066]: 2026-11-03T11:18:34.733970Z  INFO dioxus_server::server: Registering: POST /api/list_visible_time_report_entries7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  440.921519] horae[1066]: 2026-11-03T11:18:34.734215Z  INFO dioxus_server::server: Registering: POST /api/list_visible_time_report_groups7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  440.923705] horae[1066]: 2026-11-03T11:18:34.734400Z  INFO dioxus_server::server: Registering: POST /api/get_time_report_access7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  440.925207] horae[1066]: 2026-11-03T11:18:34.734552Z  INFO dioxus_server::server: Registering: POST /api/get_plugin_widgets7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  440.927605] horae[1066]: 2026-11-03T11:18:34.748006Z  INFO dioxus_server::server: Registering: POST /api/report_detailed7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  440.961602] horae[1066]: 2026-11-03T11:18:34.748296Z  INFO dioxus_server::server: Registering: POST /api/report_time7690553569863186185
vm-test-run-horae-e2e-oidc> server # [  440.977489] horae[1066]: 2026-11-03T11:18:34.748489Z  INFO dioxus_server::server: Registering: POST /api/set_user_active13739675588719463496
vm-test-run-horae-e2e-oidc> server # [  440.980004] horae[1066]: 2026-11-03T11:18:34.748649Z  INFO dioxus_server::server: Registering: POST /api/set_user_role13739675588719463496
vm-test-run-horae-e2e-oidc> server # [  441.010660] horae[1066]: 2026-11-03T11:18:34.748907Z  INFO dioxus_server::server: Registering: POST /api/list_people13739675588719463496
vm-test-run-horae-e2e-oidc> server # [  441.025316] horae[1066]: 2026-11-03T11:18:34.749093Z  INFO dioxus_server::server: Registering: POST /api/create_user13739675588719463496
vm-test-run-horae-e2e-oidc> server # [  441.027657] horae[1066]: 2026-11-03T11:18:34.749339Z  INFO dioxus_server::server: Registering: POST /api/list_users13739675588719463496
vm-test-run-horae-e2e-oidc> server # [  441.039065] horae[1066]: 2026-11-03T11:18:34.749496Z  INFO dioxus_server::server: Registering: POST /api/save_project_managers11474746963446121934
vm-test-run-horae-e2e-oidc> server # [  441.050161] horae[1066]: 2026-11-03T11:18:34.749650Z  INFO dioxus_server::server: Registering: POST /api/load_project_managers11474746963446121934
vm-test-run-horae-e2e-oidc> server # [  441.051823] horae[1066]: 2026-11-03T11:18:34.749793Z  INFO dioxus_server::server: Registering: POST /api/list_visible_time_entries16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.062852] horae[1066]: 2026-11-03T11:18:34.749948Z  INFO dioxus_server::server: Registering: POST /api/list_time_entry_contexts16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.073627] horae[1066]: 2026-11-03T11:18:34.750086Z  INFO dioxus_server::server: Registering: POST /api/reorder_untimed_entries16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.075879] horae[1066]: 2026-11-03T11:18:34.750331Z  INFO dioxus_server::server: Registering: POST /api/load_timesheet_tracking16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.101178] horae[1066]: 2026-11-03T11:18:34.750512Z  INFO dioxus_server::server: Registering: POST /api/apply_timesheet_command16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.103465] horae[1066]: 2026-11-03T11:18:34.767679Z  INFO dioxus_server::server: Registering: POST /api/reschedule_time_entry16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.114766] horae[1066]: 2026-11-03T11:18:34.767916Z  INFO dioxus_server::server: Registering: POST /api/list_timesheet_people16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.129312] horae[1066]: 2026-11-03T11:18:34.768084Z  INFO dioxus_server::server: Registering: POST /api/load_timesheet_page16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.131608] horae[1066]: 2026-11-03T11:18:34.768308Z  INFO dioxus_server::server: Registering: POST /api/update_time_entry16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.138205] horae[1066]: 2026-11-03T11:18:34.768531Z  INFO dioxus_server::server: Registering: POST /api/list_time_entries16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.153047] horae[1066]: 2026-11-03T11:18:34.768731Z  INFO dioxus_server::server: Registering: POST /api/get_current_timer16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.155143] horae[1066]: 2026-11-03T11:18:34.769169Z  INFO dioxus_server::server: Registering: POST /api/delete_time_entry16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.165723] horae[1066]: 2026-11-03T11:18:34.769368Z  INFO dioxus_server::server: Registering: POST /api/create_time_entry16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.167974] horae[1066]: 2026-11-03T11:18:34.769589Z  INFO dioxus_server::server: Registering: POST /api/start_timer16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.183414] horae[1066]: 2026-11-03T11:18:34.769818Z  INFO dioxus_server::server: Registering: POST /api/stop_timer16386063561583833955
vm-test-run-horae-e2e-oidc> server # [  441.190403] horae[1066]: 2026-11-03T11:18:34.769997Z  INFO dioxus_server::server: Registering: POST /api/update_org_branding13047172052397277026
vm-test-run-horae-e2e-oidc> server # [  441.203818] horae[1066]: 2026-11-03T11:18:34.770177Z  INFO dioxus_server::server: Registering: POST /api/get_org_branding13047172052397277026
vm-test-run-horae-e2e-oidc> server # [  441.214490] horae[1066]: 2026-11-03T11:18:34.770483Z  INFO dioxus_server::server: Registering: POST /api/get_week_start13047172052397277026
vm-test-run-horae-e2e-oidc> server # [  441.225221] horae[1066]: 2026-11-03T11:18:34.770658Z  INFO dioxus_server::server: Registering: POST /api/get_org_name13047172052397277026
vm-test-run-horae-e2e-oidc> server # [  441.237093] horae[1066]: 2026-11-03T11:18:34.770881Z  INFO dioxus_server::server: Registering: POST /api/logout16144359270796124307
vm-test-run-horae-e2e-oidc> server # [  441.239637] horae[1066]: 2026-11-03T11:18:34.791780Z  INFO dioxus_server::server: Registering: POST /api/get_me16144359270796124307
vm-test-run-horae-e2e-oidc> server # [  441.249944] horae[1066]: 2026-11-03T11:18:34.792239Z  INFO dioxus_server::server: Registering: POST /api/list_permission_audit16144359270796124307
vm-test-run-horae-e2e-oidc> server # [  441.252018] horae[1066]: 2026-11-03T11:18:34.792442Z  INFO dioxus_server::server: Registering: POST /api/get_permission_audit16144359270796124307
vm-test-run-horae-e2e-oidc> server # [  441.262499] horae[1066]: 2026-11-03T11:18:34.792615Z  INFO dioxus_server::server: Registering: POST /api/get_my_permissions16144359270796124307
vm-test-run-horae-e2e-oidc> server # [  441.273409] horae[1066]: 2026-11-03T11:18:34.967929Z  INFO horae: Listening on 127.0.0.1:3000
vm-test-run-horae-e2e-oidc> server # [  455.211753] dex[655]: time=2026-11-03T11:18:50.232Z level=INFO msg="login successful" connector_id=mock username="Kilgore Trout" preferred_username="" email=kilgore@kilgore.trout groups=[authors] request_id=36265032-0b68-4f17-8e85-7e0ed286002b
vm-test-run-horae-e2e-oidc> server # [  456.518711] systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.
vm-test-run-horae-e2e-oidc> server # [  456.549656] systemd[1]: Stopped Virtual Console Setup.
vm-test-run-horae-e2e-oidc> server # [  456.565531] systemd[1]: systemd-vconsole-setup.service: Consumed 887ms CPU time over 3min 2.976s wall clock time, 3.5M memory peak, 1.1M read from disk.
vm-test-run-horae-e2e-oidc> server # [  456.585909] systemd[1]: Stopping Virtual Console Setup...
vm-test-run-horae-e2e-oidc> server # [  456.774202] systemd[1]: Starting Virtual Console Setup...
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: dex-id-token horae-omit-email-verified horae-omit-e2e-secret, in 16.56 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: curl -sS -c /tmp/jar3.txt -b /tmp/jar3.txt -L --max-redirs 8 http://127.0.0.1:3000/auth/oidc/start -o /dev/null
vm-test-run-horae-e2e-oidc> server # [  458.956014] dex[655]: time=2026-11-03T11:18:53.977Z level=INFO msg="login successful" connector_id=mock username="Kilgore Trout" preferred_username="" email=kilgore@kilgore.trout groups=[authors] request_id=820a0630-21c7-4d10-a567-87c115b1f509
vm-test-run-horae-e2e-oidc> server # [  459.810232] systemd-vconsole-setup[1091]: Configuration of first virtual console was skipped, ignoring remaining ones.
vm-test-run-horae-e2e-oidc> server # [  459.959634] horae[1066]: 2026-11-03T11:18:54.964215Z  WARN call: horae::auth::oidc: OIDC login denied: no account for subject/email
vm-test-run-horae-e2e-oidc> server # [  460.057591] systemd[1]: Finished Virtual Console Setup.
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: curl -sS -c /tmp/jar3.txt -b /tmp/jar3.txt -L --max-redirs 8 http://127.0.0.1:3000/auth/oidc/start -o /dev/null, in 3.45 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: curl -sS -o /dev/null -w '%{http_code}' -b /tmp/jar3.txt http://127.0.0.1:3000/harvest/v2/time_entries
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: curl -sS -o /dev/null -w '%{http_code}' -b /tmp/jar3.txt http://127.0.0.1:3000/harvest/v2/time_entries, in 1.01 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: sudo -u horae psql horae -tAc 'SELECT oidc_issuer IS NULL AND oidc_subject IS NULL FROM users WHERE email = '"'"'kilgore@kilgore.trout'"'"''
vm-test-run-horae-e2e-oidc> server # [  462.131627] systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
vm-test-run-horae-e2e-oidc> server # [  462.486578] sudo[1101]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; COMMAND=/run/current-system/sw/bin/psql horae -tAc 'SELECT oidc_issuer IS NULL AND oidc_subject IS NULL FROM users WHERE email = \'kilgore@kilgore.trout\''
vm-test-run-horae-e2e-oidc> server # [  462.603147] systemd-logind[517]: Watching system buttons on /dev/input/event3 (QEMU Virtio Keyboard)
vm-test-run-horae-e2e-oidc> server # [  463.725929] sudo[1101]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  464.409263] sudo[1101]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: sudo -u horae psql horae -tAc 'SELECT oidc_issuer IS NULL AND oidc_subject IS NULL FROM users WHERE email = '"'"'kilgore@kilgore.trout'"'"'', in 3.27 seconds)
vm-test-run-horae-e2e-oidc> server # [  465.631134] sudo[1112]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; COMMAND=/run/current-system/sw/bin/env DATABASE_URL=postgres:///horae HORAE_OIDC_ISSUER=http://127.0.0.1:5556/dex horae user link-oidc --user-id 01a1a120-b834-74c0-85e1-f4aab2453f38 --issuer http://127.0.0.1:5556/dex --subject Cg0wLTM4NS0yODA4OS0wEgRtb2Nr
vm-test-run-horae-e2e-oidc> server # [  466.799851] sudo[1112]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  467.262511] sudo[1112]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server # [  467.892877] sudo[1123]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; COMMAND=/run/current-system/sw/bin/env DATABASE_URL=postgres:///horae HORAE_OIDC_ISSUER=http://127.0.0.1:5556/dex horae user link-oidc --user-id 01a1a120-b834-74c0-85e1-f4aab2453f38 --issuer http://127.0.0.1:5556/dex --subject Cg0wLTM4NS0yODA4OS0wEgRtb2Nr
vm-test-run-horae-e2e-oidc> server # [  468.595143] sudo[1123]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  469.031315] sudo[1123]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server # [  469.648059] sudo[1133]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; COMMAND=/run/current-system/sw/bin/env DATABASE_URL=postgres:///horae HORAE_OIDC_ISSUER=http://127.0.0.1:5556/dex horae user create --email other@kilgore.trout --name Other --role member
vm-test-run-horae-e2e-oidc> server # [  470.331150] sudo[1133]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  471.159638] sudo[1133]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server: must succeed: sudo -u horae psql horae -tAc 'SELECT id FROM users WHERE email = '"'"'other@kilgore.trout'"'"''
vm-test-run-horae-e2e-oidc> server # [  471.737465] sudo[1140]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; COMMAND=/run/current-system/sw/bin/psql horae -tAc 'SELECT id FROM users WHERE email = \'other@kilgore.trout\''
vm-test-run-horae-e2e-oidc> server # [  472.386265] sudo[1140]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  472.785753] sudo[1140]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: sudo -u horae psql horae -tAc 'SELECT id FROM users WHERE email = '"'"'other@kilgore.trout'"'"'', in 1.60 seconds)
vm-test-run-horae-e2e-oidc> server # [  473.487044] sudo[1151]:     root : TTY=hvc0 ; PWD=/tmp ; USER=horae ; COMMAND=/run/current-system/sw/bin/env DATABASE_URL=postgres:///horae HORAE_OIDC_ISSUER=http://127.0.0.1:5556/dex horae user link-oidc --user-id 01a1a122-5bc5-7403-a28a-38be4aa7fb1b --issuer http://127.0.0.1:5556/dex --subject Cg0wLTM4NS0yODA4OS0wEgRtb2Nr
vm-test-run-horae-e2e-oidc> server # [  474.241867] sudo[1151]: pam_unix(sudo:session): session opened for user horae(uid=63319) by (uid=0)
vm-test-run-horae-e2e-oidc> server # [  474.698511] postgres[1156]: [1156] LOG:  could not receive data from client: Connection reset by peer
vm-test-run-horae-e2e-oidc> server # [  474.731450] sudo[1151]: pam_unix(sudo:session): session closed for user horae
vm-test-run-horae-e2e-oidc> server: must succeed: curl -sS -c /tmp/jar4.txt -b /tmp/jar4.txt -L --max-redirs 8 http://127.0.0.1:3000/auth/oidc/start -o /dev/null
vm-test-run-horae-e2e-oidc> server # [  475.521708] dex[655]: time=2026-11-03T11:19:10.550Z level=INFO msg="login successful" connector_id=mock username="Kilgore Trout" preferred_username="" email=kilgore@kilgore.trout groups=[authors] request_id=de46288a-78d6-4d48-9bcb-b782563714c7
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: curl -sS -c /tmp/jar4.txt -b /tmp/jar4.txt -L --max-redirs 8 http://127.0.0.1:3000/auth/oidc/start -o /dev/null, in 1.13 seconds)
vm-test-run-horae-e2e-oidc> server: must succeed: curl -sS -o /dev/null -w '%{http_code}' -b /tmp/jar4.txt http://127.0.0.1:3000/harvest/v2/time_entries
vm-test-run-horae-e2e-oidc> server: (finished: must succeed: curl -sS -o /dev/null -w '%{http_code}' -b /tmp/jar4.txt http://127.0.0.1:3000/harvest/v2/time_entries, in 1.09 seconds)
vm-test-run-horae-e2e-oidc> (finished: run the VM test script, in 483.05 seconds)
vm-test-run-horae-e2e-oidc> test script finished in 483.41s
vm-test-run-horae-e2e-oidc> cleanup
vm-test-run-horae-e2e-oidc> kill QemuMachine (pid 12)
vm-test-run-horae-e2e-oidc> server # qemu-system-aarch64: terminating on signal 15 from pid 6 (/nix/store/smwd56pl54f0pcjdspgh5vnf20c8xwsc-python3-3.13.13/bin/python3.13)
vm-test-run-horae-e2e-oidc> (finished: cleanup, in 0.15 seconds)