container-test-run-dm-dns
default.checks.aarch64-linux.dm-dns
· build #364
· raw
1Machine state will be reset. To keep it, pass --keep-machine-state2start all VLans3(finished: start all VLans, in 0.00 seconds)45Test will time out and terminate in 3600.0 seconds6run the VM test script7additionally exposed symbols:8 client, server,9 vlan1,10 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_ssh11start all VMs12client: systemd-nspawn running (pid 52)13server: systemd-nspawn running (pid 53)14client: Waiting for journal at /build/vm-state-client/var/log/journal...15server: Waiting for journal at /build/vm-state-server/var/log/journal...16(finished: start all VMs, in 0.00 seconds)17server: waiting for unit unbound.service18nixos-nspawn(server): TAP vde-tap1 not found; container will be isolated from VDE19nixos-nspawn(server): A common reason for this is that /dev/net is not available in the Nix sandbox. Try adding /dev/net to extra-sandbox-paths.20nixos-nspawn(client): TAP vde-tap1 not found; container will be isolated from VDE21nixos-nspawn(client): A common reason for this is that /dev/net is not available in the Nix sandbox. Try adding /dev/net to extra-sandbox-paths.22Note: in a future version of systemd-nspawn the default set of permitted socket address families will be restricted to AF_INET, AF_INET6 and AF_UNIX. Use --restrict-address-families= to configure the set of permitted socket address families, or set RestrictAddressFamilies= in a .nspawn file.23░ Spawning container server on /build/vm-state-server.24Note: in a future version of systemd-nspawn the default set of permitted socket address families will be restricted to AF_INET, AF_INET6 and AF_UNIX. Use --restrict-address-families= to configure the set of permitted socket address families, or set RestrictAddressFamilies= in a .nspawn file.25░ Spawning container client on /build/vm-state-client.26client # No journal boot entry found for the specified boot (+0).27server # No journal boot entry found for the specified boot (+0).28client # [5827260.930177] client systemd-journald[86]: Journal started29client # [5827260.930233] client systemd-journald[86]: Runtime Journal (/run/log/journal/292d9ce6e61641d3afb1b00f54f7b93d) is 8M, max 2.5G, 2.4G free.30client # [5827260.931938] client systemd[1]: Finished Create Static Device Nodes in /dev gracefully.31client # [5827260.940923] client systemd[1]: Starting Flush Journal to Persistent Storage...32client # [5827260.941689] client systemd[1]: Starting Network Name Resolution...33client # [5827260.942313] client systemd[1]: Starting Create Static Device Nodes in /dev...34client # [5827260.950551] client systemd-journald[86]: Time spent on flushing to /var/log/journal/292d9ce6e61641d3afb1b00f54f7b93d is 1.175ms for 6 entries.35client # [5827260.950551] client systemd-journald[86]: System Journal (/var/log/journal/292d9ce6e61641d3afb1b00f54f7b93d) is 8M, max 4G, 3.9G free.36client # [5827260.961073] client systemd[1]: Finished Create Static Device Nodes in /dev.37client # [5827260.961722] client systemd[1]: Reached target Preparation for Local File Systems.38client # [5827260.961857] client systemd[1]: Reached target Local File Systems.39client # [5827260.962811] client systemd[1]: Listening on Boot Loader Control Service Socket.40client # [5827260.962859] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container41client # [5827260.963915] client systemd[1]: Starting Save Transient machine-id to Disk...42client # [5827260.963955] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys43client # [5827260.987725] client systemd[1]: Finished Flush Journal to Persistent Storage.44client # [5827260.989176] client systemd[1]: Starting Create System Files and Directories...45client # [5827261.007182] client systemd-tmpfiles[144]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted46client # [5827261.007390] client systemd-tmpfiles[144]: fchmod() of /var/log/journal failed: Operation not permitted47client # [5827261.007534] client systemd-tmpfiles[144]: fchmod() of /var/log/journal/292d9ce6e61641d3afb1b00f54f7b93d failed: Operation not permitted48client # [5827261.007763] client systemd-tmpfiles[144]: fchmod() of /run/log/journal failed: Operation not permitted49client # [5827261.009359] client systemd[1]: Finished Create System Files and Directories.50client # [5827261.010600] client systemd[1]: Starting Rebuild Journal Catalog...51client # [5827261.011329] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...52client # [5827261.023511] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.53client # [5827261.032576] client systemd[1]: Finished Rebuild Journal Catalog.54client # [5827261.033569] client systemd[1]: Starting Update is Completed...55client # [5827261.042590] client systemd[1]: Finished Update is Completed.56client # [5827261.081507] client systemd[1]: Finished Firewall.57client # [5827261.081659] client systemd[1]: Reached target Preparation for Network.58client # [5827261.081889] client systemd[1]: Listening on Network Management Resolve Hook Socket.59client # [5827261.082973] client systemd[1]: Starting Network Management...60client # [5827261.128650] client systemd[1]: Finished Save Transient machine-id to Disk.61client # [5827261.473844] client systemd-networkd[203]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted62client # [5827261.473942] client systemd-networkd[203]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted63client # [5827261.480449] client systemd-networkd[203]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.64client # [5827261.480616] client systemd-networkd[203]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.65client # [5827261.480786] client systemd-networkd[203]: lo: Link UP66client # [5827261.480791] client systemd-networkd[203]: lo: Gained carrier67client # [5827261.481003] client systemd-networkd[203]: eth1: Configuring with /etc/systemd/network/40-eth1.network.68server # [5827260.928353] server systemd-journald[96]: Journal started69server # [5827260.928420] server systemd-journald[96]: Runtime Journal (/run/log/journal/b777c17c63b74b6bbb9d38bf08ffc9c5) is 8M, max 2.5G, 2.4G free.70server # [5827260.930517] server systemd[1]: Finished Create Static Device Nodes in /dev gracefully.71server # [5827260.939519] server systemd[1]: Starting Flush Journal to Persistent Storage...72client # [5827261.481412] client systemd[1]: Started Network Management.73server # [5827260.940424] server systemd[1]: Starting Network Name Resolution...74server # [5827260.941114] server systemd[1]: Starting Create Static Device Nodes in /dev...75server # [5827260.949902] server systemd-journald[96]: Time spent on flushing to /var/log/journal/b777c17c63b74b6bbb9d38bf08ffc9c5 is 1.254ms for 6 entries.76server # [5827260.949902] server systemd-journald[96]: System Journal (/var/log/journal/b777c17c63b74b6bbb9d38bf08ffc9c5) is 8M, max 4G, 3.9G free.77server # [5827260.956304] server systemd[1]: Finished Create Static Device Nodes in /dev.78client # [5827261.481470] client systemd-networkd[203]: eth1: Link UP79client # [5827261.481889] client systemd-networkd[203]: eth1: Gained carrier80server # [5827260.956521] server systemd[1]: Reached target Preparation for Local File Systems.81client # [5827261.483101] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd...82client # [5827261.529233] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd.83client # [5827261.551784] client systemd-resolved[112]: Positive Trust Anchors:84client # [5827261.551797] client systemd-resolved[112]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d85server # [5827260.956598] server systemd[1]: Reached target Local File Systems.86client # [5827261.551800] client systemd-resolved[112]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b1687client # [5827261.551836] client systemd-resolved[112]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 170.0.0.192.in-addr.arpa 171.0.0.192.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa ipv4only.arpa resolver.arpa corp home internal intranet lan local private test88client # [5827261.573824] client systemd-resolved[112]: Using system hostname 'client'.89client # [5827261.575199] client systemd[1]: Started Network Name Resolution.90client # [5827261.575268] client systemd[1]: Reached target Network.91client # [5827261.575336] client systemd[1]: Reached target System Initialization.92client # [5827261.575419] client systemd[1]: Started Watch for zone file changes.93server # [5827260.957294] server systemd[1]: Listening on Boot Loader Control Service Socket.94client # [5827261.575445] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container95client # [5827261.575466] client systemd[1]: Started Daily Cleanup of Temporary Directories.96client # [5827261.575481] client systemd[1]: Reached target Path Units.97server # [5827260.957335] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container98client # [5827261.575509] client systemd[1]: Reached target Timer Units.99client # [5827261.575624] client systemd[1]: Listening on D-Bus System Message Bus Socket.100client # [5827261.575730] client systemd[1]: Listening on Nix Daemon Socket.101server # [5827260.958197] server systemd[1]: Starting Save Transient machine-id to Disk...102client # [5827261.575839] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.103server # [5827260.958230] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys104client # [5827261.575861] client systemd[1]: Reached target Socket Units.105server # [5827260.995184] server systemd[1]: Finished Flush Journal to Persistent Storage.106client # [5827261.575898] client systemd[1]: Reached target Basic System.107server # [5827260.996638] server systemd[1]: Starting Create System Files and Directories...108client # [5827261.577148] client systemd[1]: Starting data mesher daemon...109server # [5827261.011061] server systemd-tmpfiles[155]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted110client # [5827261.577795] client systemd[1]: Starting Import lastlog data into lastlog2 database...111server # [5827261.011224] server systemd-tmpfiles[155]: fchmod() of /var/log/journal failed: Operation not permitted112client # [5827261.578524] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...113server # [5827261.011340] server systemd-tmpfiles[155]: fchmod() of /var/log/journal/b777c17c63b74b6bbb9d38bf08ffc9c5 failed: Operation not permitted114client # [5827261.579566] client systemd[1]: Starting D-Bus System Message Bus...115server # [5827261.011511] server systemd-tmpfiles[155]: fchmod() of /run/log/journal failed: Operation not permitted116client # [5827261.595001] client systemd[1]: Finished Import lastlog data into lastlog2 database.117server # [5827261.015085] server systemd[1]: Finished Create System Files and Directories.118client # [5827261.678214] client nsncd[211]: Aug 15 10:04:47.731 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"119server # [5827261.016329] server systemd[1]: Starting Rebuild Journal Catalog...120client # [5827261.678797] client systemd[1]: Started Name Service Cache Daemon (nsncd).121server # [5827261.017035] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...122client # [5827261.678939] client systemd[1]: Reached target User and Group Name Lookups.123server # [5827261.027543] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.124client # [5827261.680043] client systemd[1]: Starting User Login Management...125server # [5827261.035814] server systemd[1]: Finished Rebuild Journal Catalog.126client # [5827261.680974] client systemd[1]: Starting Permit User Sessions...127server # [5827261.036792] server systemd[1]: Starting Update is Completed...128client # [5827261.690215] client systemd[1]: Finished Permit User Sessions.129server # [5827261.046280] server systemd[1]: Finished Update is Completed.130client # [5827261.691109] client systemd[1]: Started Console Getty.131server # [5827261.083678] server systemd[1]: Finished Firewall.132client # [5827261.691148] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0133server # [5827261.083833] server systemd[1]: Reached target Preparation for Network.134client # [5827261.691167] client systemd[1]: Reached target Login Prompts.135server # [5827261.084062] server systemd[1]: Listening on Network Management Resolve Hook Socket.136client # [5827261.762527] client dbus-broker-launch[212]: Looking up NSS user entry for 'systemd-timesync'...137server # [5827261.085058] server systemd[1]: Starting Network Management...138client # [5827261.763622] client dbus-broker-launch[212]: NSS returned no entry for 'systemd-timesync'139server # [5827261.128773] server systemd[1]: Finished Save Transient machine-id to Disk.140client # [5827261.763622] client dbus-broker-launch[212]: Invalid user-name in /nix/store/34pfg4kv6hqj9cxa75y076x888fk8h9d-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"141server # [5827261.476930] server systemd-networkd[213]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted142client # [5827261.764045] client systemd[1]: Started D-Bus System Message Bus.143server # [5827261.477018] server systemd-networkd[213]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted144client # [5827261.771519] client dbus-broker-launch[212]: Ready145server # [5827261.483505] server systemd-networkd[213]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.146client # [5827261.923388] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.147server # [5827261.483665] server systemd-networkd[213]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.148server # [5827261.483821] server systemd-networkd[213]: lo: Link UP149server # [5827261.483826] server systemd-networkd[213]: lo: Gained carrier150server # [5827261.484042] server systemd-networkd[213]: eth1: Configuring with /etc/systemd/network/40-eth1.network.151server # [5827261.484468] server systemd[1]: Started Network Management.152server # [5827261.484496] server systemd-networkd[213]: eth1: Link UP153server # [5827261.484794] server systemd-networkd[213]: eth1: Gained carrier154server # [5827261.486024] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...155server # [5827261.529406] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.156server # [5827261.543040] server systemd-resolved[119]: Positive Trust Anchors:157server # [5827261.543051] server systemd-resolved[119]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d158server # [5827261.543055] server systemd-resolved[119]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16159server # [5827261.543089] server systemd-resolved[119]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 170.0.0.192.in-addr.arpa 171.0.0.192.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa ipv4only.arpa resolver.arpa corp home internal intranet lan local private test160server # [5827261.565016] server systemd-resolved[119]: Using system hostname 'server'.161server # [5827261.566335] server systemd[1]: Started Network Name Resolution.162server # [5827261.566408] server systemd[1]: Reached target Network.163server # [5827261.566474] server systemd[1]: Reached target System Initialization.164server # [5827261.566557] server systemd[1]: Started Watch for zone file changes.165server # [5827261.566589] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container166server # [5827261.566615] server systemd[1]: Started Daily Cleanup of Temporary Directories.167server # [5827261.566634] server systemd[1]: Reached target Path Units.168server # [5827261.566660] server systemd[1]: Reached target Timer Units.169server # [5827261.566770] server systemd[1]: Listening on D-Bus System Message Bus Socket.170server # [5827261.566884] server systemd[1]: Listening on Nix Daemon Socket.171server # [5827261.566987] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.172server # [5827261.567007] server systemd[1]: Reached target Socket Units.173server # [5827261.567039] server systemd[1]: Reached target Basic System.174server # [5827261.568312] server systemd[1]: Starting data mesher daemon...175server # [5827261.569000] server systemd[1]: Starting Import lastlog data into lastlog2 database...176server # [5827261.569736] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...177server # [5827261.571110] server systemd[1]: Starting D-Bus System Message Bus...178server # [5827261.586263] server systemd[1]: Finished Import lastlog data into lastlog2 database.179server # [5827261.674880] server systemd[1]: Started Name Service Cache Daemon (nsncd).180server # [5827261.674957] server systemd[1]: Reached target User and Group Name Lookups.181server # [5827261.675083] server nsncd[221]: Aug 15 10:04:47.728 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"182server # [5827261.676175] server systemd[1]: Starting User Login Management...183server # [5827261.677013] server systemd[1]: Starting Permit User Sessions...184server # [5827261.686047] server systemd[1]: Finished Permit User Sessions.185server # [5827261.687137] server systemd[1]: Started Console Getty.186server # [5827261.687184] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0187server # [5827261.687206] server systemd[1]: Reached target Login Prompts.188server # [5827261.769878] server dbus-broker-launch[222]: Looking up NSS user entry for 'systemd-timesync'...189server # [5827261.770710] server dbus-broker-launch[222]: NSS returned no entry for 'systemd-timesync'190server # [5827261.770747] server dbus-broker-launch[222]: Invalid user-name in /nix/store/mw09sd9lc4rkfs3qb2pj6pghkqgsk711-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"191server # [5827261.771130] server systemd[1]: Started D-Bus System Message Bus.192server # [5827261.777922] server dbus-broker-launch[222]: Ready193server # [5827261.923328] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.194client # [5827261.992146] client data-mesher[209]: time=2026-08-15T10:04:48.045Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]195client # [5827261.993267] client data-mesher[209]: time=2026-08-15T10:04:48.046Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo: [/dns/client.test/tcp/7946]} {12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo196client # [5827261.993267] client data-mesher[209]: time=2026-08-15T10:04:48.046Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml197client # [5827262.020849] client data-mesher[209]: time=2026-08-15T10:04:48.073Z level=INFO msg="checking file integrity"198client # [5827262.020928] client data-mesher[209]: time=2026-08-15T10:04:48.074Z level=INFO msg="file integrity check complete"199server # [5827262.011520] server data-mesher[219]: time=2026-08-15T10:04:48.064Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]200server # [5827262.012590] server data-mesher[219]: time=2026-08-15T10:04:48.065Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo: [/dns/client.test/tcp/7946]} {12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL201server # [5827262.012629] server data-mesher[219]: time=2026-08-15T10:04:48.065Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml202server # [5827262.021102] server data-mesher[219]: time=2026-08-15T10:04:48.073Z level=INFO msg="checking file integrity"203server # [5827262.021102] server data-mesher[219]: time=2026-08-15T10:04:48.074Z level=INFO msg="file integrity check complete"204server # [5827262.025065] server data-mesher[219]: time=2026-08-15T10:04:48.078Z level=INFO msg="libp2p host created" peer_id=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL addresses="[/ip4/127.0.0.1/tcp/7946 /ip4/192.168.1.2/tcp/7946 /ip6/::1/tcp/7946 /ip6/2001:db8:1::2/tcp/7946]"205server # [5827262.025154] server data-mesher[219]: time=2026-08-15T10:04:48.078Z level=INFO msg="registered HTTP route" method=GET path=/files206server # [5827262.025154] server data-mesher[219]: time=2026-08-15T10:04:48.078Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name207server # [5827262.025154] server data-mesher[219]: time=2026-08-15T10:04:48.078Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name208server # [5827262.025154] server data-mesher[219]: time=2026-08-15T10:04:48.078Z level=INFO msg="starting server"209server # [5827262.025277] server data-mesher[219]: time=2026-08-15T10:04:48.078Z level=INFO msg="waiting for DHT to populate" delay=10s210server # [5827262.025277] server data-mesher[219]: time=2026-08-15T10:04:48.078Z level=INFO msg="HTTP server listening" address=[::1]:7331211server # [5827262.025333] server data-mesher[219]: time=2026-08-15T10:04:48.078Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331212server # [5827262.032134] server data-mesher[219]: time=2026-08-15T10:04:48.085Z level=INFO msg="peer connected" peer_id=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo remote_addr=/ip4/192.168.1.1/tcp/7946213server # [5827262.060955] server data-mesher[219]: time=2026-08-15T10:04:48.114Z level=INFO msg="peer connected" peer_id=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo remote_addr=/ip4/192.168.1.1/tcp/42556214server # [5827262.101785] server systemd-logind[239]: New seat seat0.215server # [5827262.102072] server systemd[1]: Started User Login Management.216server # [5827262.103289] server systemd[1]: Starting linger-users.service...217server # [5827262.158462] server systemd[1]: linger-users.service: Deactivated successfully.218server # [5827262.158615] server systemd[1]: Finished linger-users.service.219client # [5827262.025604] client data-mesher[209]: time=2026-08-15T10:04:48.078Z level=INFO msg="libp2p host created" peer_id=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo addresses="[/ip4/127.0.0.1/tcp/7946 /ip4/192.168.1.1/tcp/7946 /ip6/::1/tcp/7946 /ip6/2001:db8:1::1/tcp/7946]"220client # [5827262.025604] client data-mesher[209]: time=2026-08-15T10:04:48.078Z level=INFO msg="registered HTTP route" method=GET path=/files221client # [5827262.025604] client data-mesher[209]: time=2026-08-15T10:04:48.078Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name222client # [5827262.025604] client data-mesher[209]: time=2026-08-15T10:04:48.078Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name223client # [5827262.025604] client data-mesher[209]: time=2026-08-15T10:04:48.078Z level=INFO msg="starting server"224client # [5827262.025879] client data-mesher[209]: time=2026-08-15T10:04:48.078Z level=INFO msg="waiting for DHT to populate" delay=10s225client # [5827262.025879] client data-mesher[209]: time=2026-08-15T10:04:48.078Z level=INFO msg="HTTP server listening" address=[::1]:7331226client # [5827262.025879] client data-mesher[209]: time=2026-08-15T10:04:48.079Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331227client # [5827262.032738] client data-mesher[209]: time=2026-08-15T10:04:48.085Z level=INFO msg="peer connected" peer_id=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL remote_addr=/ip4/192.168.1.2/tcp/7946228client # [5827262.059918] client data-mesher[209]: time=2026-08-15T10:04:48.113Z level=INFO msg="peer connected" peer_id=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL remote_addr=/ip4/192.168.1.2/tcp/7946229client # [5827262.109858] client systemd-logind[229]: New seat seat0.230client # [5827262.109984] client systemd[1]: Started User Login Management.231client # [5827262.148473] client systemd[1]: Starting linger-users.service...232client # [5827262.159849] client systemd[1]: linger-users.service: Deactivated successfully.233client # [5827262.159926] client systemd[1]: Finished linger-users.service.234server # [5827262.628309] server systemd-networkd[213]: eth1: Gained IPv6LL235client # [5827263.008238] client systemd-networkd[203]: eth1: Gained IPv6LL236server: still waiting for container 'server' to reach ready state...237server # [5827272.025381] server data-mesher[219]: time=2026-08-15T10:04:58.078Z level=INFO msg="performing state exchange with peers on join" count=1238server # [5827272.025381] server data-mesher[219]: time=2026-08-15T10:04:58.078Z level=DEBUG msg="initiating state exchange" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo timeout=5s239server # [5827272.026307] server data-mesher[219]: time=2026-08-15T10:04:58.079Z level=INFO msg="merging remote state" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo240server # [5827272.026307] server data-mesher[219]: time=2026-08-15T10:04:58.079Z level=INFO msg="state exchange complete" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo timeout=5s241client # [5827272.025752] client data-mesher[209]: time=2026-08-15T10:04:58.078Z level=INFO msg="performing state exchange with peers on join" count=1242server # [5827272.026307] server data-mesher[219]: time=2026-08-15T10:04:58.079Z level=INFO msg="received state sync from peer" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo243client # [5827272.025752] client data-mesher[209]: time=2026-08-15T10:04:58.078Z level=DEBUG msg="initiating state exchange" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL timeout=5s244server # [5827272.026489] server data-mesher[219]: time=2026-08-15T10:04:58.079Z level=INFO msg="merging remote state" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo245client # [5827272.026520] client data-mesher[209]: time=2026-08-15T10:04:58.079Z level=INFO msg="received state sync from peer" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL246server # [5827272.026489] server data-mesher[219]: time=2026-08-15T10:04:58.079Z level=INFO msg="server started"247client # [5827272.026520] client data-mesher[209]: time=2026-08-15T10:04:58.079Z level=INFO msg="merging remote state" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL248server # [5827272.026489] server data-mesher[219]: time=2026-08-15T10:04:58.079Z level=INFO msg="starting expired-file sweeper" interval=1m0s249client # [5827272.026520] client data-mesher[209]: time=2026-08-15T10:04:58.079Z level=INFO msg="merging remote state" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL250server # [5827272.026647] server systemd[1]: Started data mesher daemon.251client # [5827272.026520] client data-mesher[209]: time=2026-08-15T10:04:58.079Z level=INFO msg="state exchange complete" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL timeout=5s252server # [5827272.029095] server systemd[1]: Starting Unbound recursive Domain Name Server...253client # [5827272.026520] client data-mesher[209]: time=2026-08-15T10:04:58.079Z level=INFO msg="server started"254client # [5827272.026762] client data-mesher[209]: time=2026-08-15T10:04:58.079Z level=INFO msg="starting expired-file sweeper" interval=1m0s255client # [5827272.026701] client systemd[1]: Started data mesher daemon.256client # [5827272.029088] client systemd[1]: Starting Unbound recursive Domain Name Server...257server # [5827272.554580] server unbound-pre-start[283]: Root anchor updated!258client # [5827272.546241] client unbound-pre-start[271]: Root anchor updated!259server # [5827272.566529] server unbound-pre-start[287]: setup in directory /var/lib/unbound260client # [5827272.559582] client unbound-pre-start[275]: setup in directory /var/lib/unbound261server # [5827273.178940] server unbound-pre-start[296]: Certificate request self-signature ok262server # [5827273.178940] server unbound-pre-start[296]: subject=CN=unbound-control263server # [5827273.199939] server unbound-pre-start[287]: removing artifacts264server # [5827273.201844] server unbound-pre-start[287]: Setup success. Certificates created. Enable in unbound.conf file to use265server # [5827273.739219] server unbound[301]: [301:0] notice: init module 0: validator266server # [5827273.739326] server unbound[301]: [301:0] notice: init module 1: iterator267server # [5827273.744764] server unbound[301]: [301:0] info: start of service (unbound 1.25.2).268server # [5827273.744910] server systemd[1]: Started Unbound recursive Domain Name Server.269server # [5827273.745398] server systemd[1]: Reached target Multi-User System.270server # [5827273.745670] server systemd[1]: Reached target Host and Network Name Lookups.271server # [5827273.747483] server systemd[1]: Starting Reload unbound zone configuration...272server # [5827273.760948] server unbound[301]: [301:0] info: service stopped (unbound 1.25.2).273server # [5827273.761258] server unbound-control[304]: ok274server # [5827273.761525] server unbound[301]: [301:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting275server # [5827273.761532] server unbound[301]: [301:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0276server # [5827273.762195] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.277server # [5827273.762534] server systemd[1]: Finished Reload unbound zone configuration.278server # [5827273.763148] server systemd[1]: Startup finished in 13.262s.279server # [5827273.763332] server unbound[301]: [301:0] notice: Restart of unbound 1.25.2.280server # [5827273.764294] server unbound[301]: [301:0] notice: init module 0: validator281server # [5827273.764366] server unbound[301]: [301:0] notice: init module 1: iterator282server # [5827273.769006] server unbound[301]: [301:0] info: start of service (unbound 1.25.2).283server: (finished: waiting for unit unbound.service, in 14.17 seconds)284client: waiting for unit unbound.service285client # [5827274.307344] client unbound-pre-start[284]: Certificate request self-signature ok286client # [5827274.307344] client unbound-pre-start[284]: subject=CN=unbound-control287client # [5827274.327300] client unbound-pre-start[275]: removing artifacts288client # [5827274.328911] client unbound-pre-start[275]: Setup success. Certificates created. Enable in unbound.conf file to use289client # [5827274.859413] client unbound[289]: [289:0] notice: init module 0: validator290client # [5827274.859527] client unbound[289]: [289:0] notice: init module 1: iterator291client # [5827274.864943] client unbound[289]: [289:0] info: start of service (unbound 1.25.2).292client # [5827274.865117] client systemd[1]: Started Unbound recursive Domain Name Server.293client # [5827274.865663] client systemd[1]: Reached target Multi-User System.294client # [5827274.865939] client systemd[1]: Reached target Host and Network Name Lookups.295client # [5827274.867912] client systemd[1]: Starting Reload unbound zone configuration...296client # [5827274.880653] client unbound[289]: [289:0] info: service stopped (unbound 1.25.2).297client # [5827274.881000] client unbound[289]: [289:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting298client # [5827274.881005] client unbound[289]: [289:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0299client # [5827274.881501] client unbound-control[292]: ok300client # [5827274.882747] client unbound[289]: [289:0] notice: Restart of unbound 1.25.2.301client # [5827274.883125] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.302client # [5827274.883462] client systemd[1]: Finished Reload unbound zone configuration.303client # [5827274.883625] client unbound[289]: [289:0] notice: init module 0: validator304client # [5827274.883684] client unbound[289]: [289:0] notice: init module 1: iterator305client # [5827274.884029] client systemd[1]: Startup finished in 14.420s.306client # [5827274.888372] client unbound[289]: [289:0] info: start of service (unbound 1.25.2).307client: (finished: waiting for unit unbound.service, in 1.15 seconds)308server: waiting for unit data-mesher.service309server: (finished: waiting for unit data-mesher.service, in 0.02 seconds)310server: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1311server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1, in 0.03 seconds)312server: must succeed: data-mesher file update --network-id /nix/store/8wj77p7dx6frq1sac93hkz39xy7b3x98-shared-data-mesher-network_network.pub /nix/store/4g9kvmaqs34gisvxgf61p42p665lx8dx-shared-dm-dns_zone.conf --url http://localhost:7331 --key /run/secrets/shared/dm-dns-signing-key/signing.key --name dns/cnames313server: (finished: must succeed: data-mesher file update --network-id /nix/store/8wj77p7dx6frq1sac93hkz39xy7b3x98-shared-data-mesher-network_network.pub /nix/store/4g9kvmaqs34gisvxgf61p42p665lx8dx-shared-dm-dns_zone.conf --url http://localhost:7331 --key /run/secrets/shared/dm-dns-signing-key/signing.key --name dns/cnames, in 0.04 seconds)314??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.315 File "/nix/store/258dmf26bj4wx2idmzbn2vz4hzlmk8bh-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39316server: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test317??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.318 File "/nix/store/258dmf26bj4wx2idmzbn2vz4hzlmk8bh-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39319server # [5827275.379133] server systemd[1]: Starting Reload unbound zone configuration...320server # [5827275.383093] server data-mesher[219]: time=2026-08-15T10:05:01.436Z level=INFO msg=http_request uri=/files/dns/cnames status=204321server # [5827275.417365] server unbound[301]: [301:0] info: service stopped (unbound 1.25.2).322server # [5827275.417831] server unbound[301]: [301:0] info: server stats for thread 0: 7 queries, 2 answers from cache, 5 recursions, 0 prefetch, 0 rejected by ip ratelimiting323server # [5827275.417979] server unbound-control[339]: ok324server # [5827275.417838] server unbound[301]: [301:0] info: server stats for thread 0: requestlist max 2 avg 1.6 exceeded 0 jostled 0325server # [5827275.419197] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.326server # [5827275.419404] server unbound[301]: [301:0] notice: Restart of unbound 1.25.2.327server # [5827275.419499] server systemd[1]: Finished Reload unbound zone configuration.328server # [5827275.420591] server unbound[301]: [301:0] notice: init module 0: validator329server # [5827275.420663] server unbound[301]: [301:0] notice: init module 1: iterator330server # [5827275.426444] server unbound[301]: [301:0] info: start of service (unbound 1.25.2).331server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test, in 1.05 seconds)332(finished: run the VM test script, in 16.46 seconds)333test script finished in 16.53s334cleanup335kill NspawnMachine (pid 52)336kill NspawnMachine (pid 53)337Container client terminated by signal KILL.338Container server terminated by signal KILL.339(finished: cleanup, in 0.33 seconds)