container-test-run-dm-dns
default.checks.aarch64-linux.dm-dns
· build #354
· 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.23Note: 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.24░ Spawning container server on /build/vm-state-server.25░ Spawning container client on /build/vm-state-client.26client # [5740896.640969] client systemd-journald[87]: Journal started27client # [5740896.641024] client systemd-journald[87]: Runtime Journal (/run/log/journal/455028c0dc864719b006e4704083fc93) is 8M, max 2.5G, 2.4G free.28client # [5740896.643873] client systemd[1]: Finished Create Static Device Nodes in /dev gracefully.29client # [5740896.653840] client systemd[1]: Starting Flush Journal to Persistent Storage...30client # [5740896.654738] client systemd[1]: Starting Network Name Resolution...31client # [5740896.655582] client systemd[1]: Starting Create Static Device Nodes in /dev...32client # [5740896.663807] client systemd-journald[87]: Time spent on flushing to /var/log/journal/455028c0dc864719b006e4704083fc93 is 1.621ms for 6 entries.33client # [5740896.663807] client systemd-journald[87]: System Journal (/var/log/journal/455028c0dc864719b006e4704083fc93) is 8M, max 4G, 3.9G free.34client # [5740896.675487] client systemd[1]: Finished Create Static Device Nodes in /dev.35client # [5740896.676223] client systemd[1]: Reached target Preparation for Local File Systems.36client # [5740896.676364] client systemd[1]: Reached target Local File Systems.37client # [5740896.677218] client systemd[1]: Listening on Boot Loader Control Service Socket.38client # [5740896.677263] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container39client # [5740896.678138] client systemd[1]: Starting Save Transient machine-id to Disk...40client # [5740896.678174] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys41client # [5740896.744049] client systemd[1]: Finished Flush Journal to Persistent Storage.42client # [5740896.745664] client systemd[1]: Starting Create System Files and Directories...43client # [5740896.761110] client systemd-tmpfiles[148]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted44client # [5740896.761312] client systemd-tmpfiles[148]: fchmod() of /var/log/journal failed: Operation not permitted45client # [5740896.761464] client systemd-tmpfiles[148]: fchmod() of /var/log/journal/455028c0dc864719b006e4704083fc93 failed: Operation not permitted46client # [5740896.761678] client systemd-tmpfiles[148]: fchmod() of /run/log/journal failed: Operation not permitted47server # [5740896.637958] server systemd-journald[96]: Journal started48server # [5740896.638015] server systemd-journald[96]: Runtime Journal (/run/log/journal/d50e255ba43446b1b0a8f2075de7b2ef) is 8M, max 2.5G, 2.4G free.49server # [5740896.643623] server systemd[1]: Finished Create Static Device Nodes in /dev gracefully.50server # [5740896.654110] server systemd[1]: Starting Flush Journal to Persistent Storage...51server # [5740896.655039] server systemd[1]: Starting Network Name Resolution...52server # [5740896.655768] server systemd[1]: Starting Create Static Device Nodes in /dev...53server # [5740896.663871] server systemd-journald[96]: Time spent on flushing to /var/log/journal/d50e255ba43446b1b0a8f2075de7b2ef is 1.754ms for 6 entries.54server # [5740896.663871] server systemd-journald[96]: System Journal (/var/log/journal/d50e255ba43446b1b0a8f2075de7b2ef) is 8M, max 4G, 3.9G free.55server # [5740896.670969] server systemd[1]: Finished Create Static Device Nodes in /dev.56server # [5740896.671234] server systemd[1]: Reached target Preparation for Local File Systems.57server # [5740896.671328] server systemd[1]: Reached target Local File Systems.58server # [5740896.672118] server systemd[1]: Listening on Boot Loader Control Service Socket.59server # [5740896.672164] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container60server # [5740896.673058] server systemd[1]: Starting Save Transient machine-id to Disk...61server # [5740896.673094] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys62server # [5740896.732815] server systemd[1]: Finished Flush Journal to Persistent Storage.63server # [5740896.734440] server systemd[1]: Starting Create System Files and Directories...64server # [5740896.750241] server systemd-tmpfiles[170]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted65server # [5740896.750453] server systemd-tmpfiles[170]: fchmod() of /var/log/journal failed: Operation not permitted66server # [5740896.750601] server systemd-tmpfiles[170]: fchmod() of /var/log/journal/d50e255ba43446b1b0a8f2075de7b2ef failed: Operation not permitted67server # [5740896.750834] server systemd-tmpfiles[170]: fchmod() of /run/log/journal failed: Operation not permitted68server # [5740896.752312] server systemd[1]: Finished Create System Files and Directories.69server # [5740896.753494] server systemd[1]: Starting Rebuild Journal Catalog...70server # [5740896.754302] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...71server # [5740896.767895] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.72server # [5740896.773318] server systemd[1]: Finished Rebuild Journal Catalog.73server # [5740896.774473] server systemd[1]: Starting Update is Completed...74server # [5740896.784915] server systemd[1]: Finished Update is Completed.75server # [5740896.858151] server systemd[1]: Finished Save Transient machine-id to Disk.76client # [5740896.763314] client systemd[1]: Finished Create System Files and Directories.77client # [5740896.764568] client systemd[1]: Starting Rebuild Journal Catalog...78client # [5740896.765375] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...79client # [5740896.777592] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.80client # [5740896.784647] client systemd[1]: Finished Rebuild Journal Catalog.81client # [5740896.785716] client systemd[1]: Starting Update is Completed...82client # [5740896.798660] client systemd[1]: Finished Update is Completed.83client # [5740896.858119] client systemd[1]: Finished Save Transient machine-id to Disk.84server # [5740896.919203] server systemd[1]: Finished Firewall.85server # [5740896.919352] server systemd[1]: Reached target Preparation for Network.86server # [5740896.919567] server systemd[1]: Listening on Network Management Resolve Hook Socket.87server # [5740896.920627] server systemd[1]: Starting Network Management...88client # [5740896.943409] client systemd[1]: Finished Firewall.89client # [5740896.943561] client systemd[1]: Reached target Preparation for Network.90client # [5740896.943774] client systemd[1]: Listening on Network Management Resolve Hook Socket.91client # [5740896.944783] client systemd[1]: Starting Network Management...92server # [5740897.315168] server systemd-networkd[214]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted93server # [5740897.315257] server systemd-networkd[214]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted94server # [5740897.321831] server systemd-networkd[214]: /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.95server # [5740897.321997] server systemd-networkd[214]: /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.96server # [5740897.322149] server systemd-networkd[214]: lo: Link UP97server # [5740897.322154] server systemd-networkd[214]: lo: Gained carrier98server # [5740897.322372] server systemd-networkd[214]: eth1: Configuring with /etc/systemd/network/40-eth1.network.99server # [5740897.322752] server systemd[1]: Started Network Management.100server # [5740897.322832] server systemd-networkd[214]: eth1: Link UP101server # [5740897.323106] server systemd-networkd[214]: eth1: Gained carrier102server # [5740897.324636] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...103server # [5740897.338176] server systemd-resolved[122]: Positive Trust Anchors:104server # [5740897.338193] server systemd-resolved[122]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d105server # [5740897.338197] server systemd-resolved[122]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16106server # [5740897.338231] server systemd-resolved[122]: 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 test107server # [5740897.360519] server systemd-resolved[122]: Using system hostname 'server'.108server # [5740897.361850] server systemd[1]: Started Network Name Resolution.109server # [5740897.361981] server systemd[1]: Reached target Network.110server # [5740897.362097] server systemd[1]: Reached target System Initialization.111server # [5740897.362273] server systemd[1]: Started Watch for zone file changes.112server # [5740897.362326] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container113server # [5740897.362377] server systemd[1]: Started Daily Cleanup of Temporary Directories.114server # [5740897.362419] server systemd[1]: Reached target Path Units.115server # [5740897.362482] server systemd[1]: Reached target Timer Units.116server # [5740897.363241] server systemd[1]: Listening on D-Bus System Message Bus Socket.117server # [5740897.363515] server systemd[1]: Listening on Nix Daemon Socket.118server # [5740897.363625] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.119server # [5740897.363648] server systemd[1]: Reached target Socket Units.120server # [5740897.363690] server systemd[1]: Reached target Basic System.121server # [5740897.364995] server systemd[1]: Starting data mesher daemon...122server # [5740897.365701] server systemd[1]: Starting Import lastlog data into lastlog2 database...123server # [5740897.366592] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...124server # [5740897.367792] server systemd[1]: Starting D-Bus System Message Bus...125server # [5740897.382313] server systemd[1]: Finished Import lastlog data into lastlog2 database.126server # [5740897.406586] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.127server # [5740897.482370] server nsncd[220]: Aug 14 10:05:23.535 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"128server # [5740897.482475] server systemd[1]: Started Name Service Cache Daemon (nsncd).129server # [5740897.482541] server systemd[1]: Reached target User and Group Name Lookups.130server # [5740897.512356] server systemd[1]: Starting User Login Management...131server # [5740897.513168] server systemd[1]: Starting Permit User Sessions...132server # [5740897.524946] server systemd[1]: Finished Permit User Sessions.133server # [5740897.526504] server systemd[1]: Started Console Getty.134server # [5740897.526549] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0135server # [5740897.526565] server systemd[1]: Reached target Login Prompts.136server # [5740897.549702] server dbus-broker-launch[221]: Looking up NSS user entry for 'systemd-timesync'...137server # [5740897.550785] server dbus-broker-launch[221]: NSS returned no entry for 'systemd-timesync'138server # [5740897.550785] server dbus-broker-launch[221]: Invalid user-name in /nix/store/yp3qary4vk31jsk8bp08c1llmbjicq7i-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"139server # [5740897.551243] server systemd[1]: Started D-Bus System Message Bus.140server # [5740897.559799] server dbus-broker-launch[221]: Ready141client # [5740897.327103] client systemd-networkd[205]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted142client # [5740897.327195] client systemd-networkd[205]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted143client # [5740897.334108] client systemd-networkd[205]: /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.144client # [5740897.334275] client systemd-networkd[205]: /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.145client # [5740897.334428] client systemd-networkd[205]: lo: Link UP146client # [5740897.334439] client systemd-networkd[205]: lo: Gained carrier147client # [5740897.334656] client systemd-networkd[205]: eth1: Configuring with /etc/systemd/network/40-eth1.network.148client # [5740897.335015] client systemd[1]: Started Network Management.149client # [5740897.335128] client systemd-networkd[205]: eth1: Link UP150client # [5740897.336194] client systemd-networkd[205]: eth1: Gained carrier151client # [5740897.336364] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd...152client # [5740897.337645] client systemd-resolved[112]: Positive Trust Anchors:153client # [5740897.337656] client systemd-resolved[112]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d154client # [5740897.337660] client systemd-resolved[112]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16155client # [5740897.337695] 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 test156client # [5740897.360333] client systemd-resolved[112]: Using system hostname 'client'.157client # [5740897.361739] client systemd[1]: Started Network Name Resolution.158client # [5740897.361813] client systemd[1]: Reached target Network.159client # [5740897.361882] client systemd[1]: Reached target System Initialization.160client # [5740897.361958] client systemd[1]: Started Watch for zone file changes.161client # [5740897.361982] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container162client # [5740897.362008] client systemd[1]: Started Daily Cleanup of Temporary Directories.163client # [5740897.362025] client systemd[1]: Reached target Path Units.164client # [5740897.362051] client systemd[1]: Reached target Timer Units.165client # [5740897.362166] client systemd[1]: Listening on D-Bus System Message Bus Socket.166client # [5740897.362281] client systemd[1]: Listening on Nix Daemon Socket.167client # [5740897.362381] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.168client # [5740897.362402] client systemd[1]: Reached target Socket Units.169client # [5740897.362435] client systemd[1]: Reached target Basic System.170client # [5740897.363668] client systemd[1]: Starting data mesher daemon...171client # [5740897.364476] client systemd[1]: Starting Import lastlog data into lastlog2 database...172client # [5740897.365447] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...173client # [5740897.366699] client systemd[1]: Starting D-Bus System Message Bus...174client # [5740897.382326] client systemd[1]: Finished Import lastlog data into lastlog2 database.175client # [5740897.406285] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd.176client # [5740897.466663] client nsncd[211]: Aug 14 10:05:23.519 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"177client # [5740897.466756] client systemd[1]: Started Name Service Cache Daemon (nsncd).178client # [5740897.466817] client systemd[1]: Reached target User and Group Name Lookups.179client # [5740897.467919] client systemd[1]: Starting User Login Management...180client # [5740897.468766] client systemd[1]: Starting Permit User Sessions...181client # [5740897.519324] client systemd[1]: Finished Permit User Sessions.182client # [5740897.520365] client systemd[1]: Started Console Getty.183client # [5740897.520408] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0184client # [5740897.520431] client systemd[1]: Reached target Login Prompts.185client # [5740897.550221] client dbus-broker-launch[212]: Looking up NSS user entry for 'systemd-timesync'...186client # [5740897.551311] client dbus-broker-launch[212]: NSS returned no entry for 'systemd-timesync'187client # [5740897.551311] 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"188client # [5740897.551367] client systemd[1]: Started D-Bus System Message Bus.189client # [5740897.560842] client dbus-broker-launch[212]: Ready190client # [5740897.641194] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.191server # [5740897.627985] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.192server # [5740897.953259] server systemd-logind[239]: New seat seat0.193client # [5740897.953644] client systemd-logind[230]: New seat seat0.194server # [5740897.953484] server systemd[1]: Started User Login Management.195client # [5740897.953852] client systemd[1]: Started User Login Management.196server # [5740897.954770] server systemd[1]: Starting linger-users.service...197client # [5740897.954948] client systemd[1]: Starting linger-users.service...198server # [5740897.998859] server systemd[1]: linger-users.service: Deactivated successfully.199client # [5740897.998464] client systemd[1]: linger-users.service: Deactivated successfully.200server # [5740897.999011] server systemd[1]: Finished linger-users.service.201client # [5740897.998647] client systemd[1]: Finished linger-users.service.202server # [5740898.012104] server data-mesher[218]: time=2026-08-14T10:05:24.065Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]203client # [5740898.012088] client data-mesher[209]: time=2026-08-14T10:05:24.065Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]204server # [5740898.013175] server data-mesher[218]: time=2026-08-14T10:05:24.066Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWDn4eFckAAFwpc4jeyWvtMnV1EE9woKQ4oXT8Mk6j9wtu: [/dns/client.test/tcp/7946]} {12D3KooWLyVZ4nzpb7YjjWECxpn5rvZimUvhp4VEc6NUgLvzTXyM: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWLyVZ4nzpb7YjjWECxpn5rvZimUvhp4VEc6NUgLvzTXyM205client # [5740898.013322] client data-mesher[209]: time=2026-08-14T10:05:24.066Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWDn4eFckAAFwpc4jeyWvtMnV1EE9woKQ4oXT8Mk6j9wtu: [/dns/client.test/tcp/7946]} {12D3KooWLyVZ4nzpb7YjjWECxpn5rvZimUvhp4VEc6NUgLvzTXyM: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWDn4eFckAAFwpc4jeyWvtMnV1EE9woKQ4oXT8Mk6j9wtu206server # [5740898.013175] server data-mesher[218]: time=2026-08-14T10:05:24.066Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml207client # [5740898.013322] client data-mesher[209]: time=2026-08-14T10:05:24.066Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml208server # [5740898.041942] server data-mesher[218]: time=2026-08-14T10:05:24.095Z level=INFO msg="checking file integrity"209client # [5740898.042111] client data-mesher[209]: time=2026-08-14T10:05:24.095Z level=INFO msg="checking file integrity"210server # [5740898.042526] server data-mesher[218]: time=2026-08-14T10:05:24.095Z level=INFO msg="file integrity check complete"211client # [5740898.042263] client data-mesher[209]: time=2026-08-14T10:05:24.095Z level=INFO msg="file integrity check complete"212server # [5740898.046494] server data-mesher[218]: time=2026-08-14T10:05:24.099Z level=INFO msg="libp2p host created" peer_id=12D3KooWLyVZ4nzpb7YjjWECxpn5rvZimUvhp4VEc6NUgLvzTXyM 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]"213client # [5740898.048523] client data-mesher[209]: time=2026-08-14T10:05:24.101Z level=INFO msg="libp2p host created" peer_id=12D3KooWDn4eFckAAFwpc4jeyWvtMnV1EE9woKQ4oXT8Mk6j9wtu 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]"214server # [5740898.046628] server data-mesher[218]: time=2026-08-14T10:05:24.099Z level=INFO msg="registered HTTP route" method=GET path=/files215client # [5740898.048630] client data-mesher[209]: time=2026-08-14T10:05:24.101Z level=INFO msg="registered HTTP route" method=GET path=/files216server # [5740898.046628] server data-mesher[218]: time=2026-08-14T10:05:24.099Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name217client # [5740898.048630] client data-mesher[209]: time=2026-08-14T10:05:24.101Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name218server # [5740898.046628] server data-mesher[218]: time=2026-08-14T10:05:24.099Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name219client # [5740898.048630] client data-mesher[209]: time=2026-08-14T10:05:24.101Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name220server # [5740898.046628] server data-mesher[218]: time=2026-08-14T10:05:24.099Z level=INFO msg="starting server"221client # [5740898.048630] client data-mesher[209]: time=2026-08-14T10:05:24.101Z level=INFO msg="starting server"222server # [5740898.046793] server data-mesher[218]: time=2026-08-14T10:05:24.099Z level=INFO msg="waiting for DHT to populate" delay=10s223client # [5740898.048739] client data-mesher[209]: time=2026-08-14T10:05:24.101Z level=INFO msg="waiting for DHT to populate" delay=10s224server # [5740898.046793] server data-mesher[218]: time=2026-08-14T10:05:24.099Z level=INFO msg="HTTP server listening" address=[::1]:7331225client # [5740898.049366] client data-mesher[209]: time=2026-08-14T10:05:24.101Z level=INFO msg="HTTP server listening" address=[::1]:7331226server # [5740898.046793] server data-mesher[218]: time=2026-08-14T10:05:24.099Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331227client # [5740898.049366] client data-mesher[209]: time=2026-08-14T10:05:24.102Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331228server # [5740898.055005] server data-mesher[218]: time=2026-08-14T10:05:24.108Z level=INFO msg="peer connected" peer_id=12D3KooWDn4eFckAAFwpc4jeyWvtMnV1EE9woKQ4oXT8Mk6j9wtu remote_addr=/ip4/192.168.1.1/tcp/7946229client # [5740898.055434] client data-mesher[209]: time=2026-08-14T10:05:24.108Z level=INFO msg="peer connected" peer_id=12D3KooWLyVZ4nzpb7YjjWECxpn5rvZimUvhp4VEc6NUgLvzTXyM remote_addr=/ip4/192.168.1.2/tcp/7946230server # [5740898.086833] server data-mesher[218]: time=2026-08-14T10:05:24.139Z level=INFO msg="peer connected" peer_id=12D3KooWDn4eFckAAFwpc4jeyWvtMnV1EE9woKQ4oXT8Mk6j9wtu remote_addr=/ip4/192.168.1.1/tcp/54476231client # [5740898.085103] client data-mesher[209]: time=2026-08-14T10:05:24.138Z level=INFO msg="peer connected" peer_id=12D3KooWLyVZ4nzpb7YjjWECxpn5rvZimUvhp4VEc6NUgLvzTXyM remote_addr=/ip4/192.168.1.2/tcp/7946232server # [5740899.044226] server systemd-networkd[214]: eth1: Gained IPv6LL233client # [5740899.168192] client systemd-networkd[205]: eth1: Gained IPv6LL234server: still waiting for container 'server' to reach ready state...235client # [5740908.048204] client data-mesher[209]: time=2026-08-14T10:05:34.101Z level=INFO msg="received state sync from peer" peer=12D3KooWLyVZ4nzpb7YjjWECxpn5rvZimUvhp4VEc6NUgLvzTXyM236client # [5740908.048204] client data-mesher[209]: time=2026-08-14T10:05:34.101Z level=INFO msg="merging remote state" peer=12D3KooWLyVZ4nzpb7YjjWECxpn5rvZimUvhp4VEc6NUgLvzTXyM237client # [5740908.049707] client data-mesher[209]: time=2026-08-14T10:05:34.102Z level=INFO msg="performing state exchange with peers on join" count=1238client # [5740908.049707] client data-mesher[209]: time=2026-08-14T10:05:34.102Z level=DEBUG msg="initiating state exchange" peer=12D3KooWLyVZ4nzpb7YjjWECxpn5rvZimUvhp4VEc6NUgLvzTXyM timeout=5s239client # [5740908.050511] client data-mesher[209]: time=2026-08-14T10:05:34.103Z level=INFO msg="merging remote state" peer=12D3KooWLyVZ4nzpb7YjjWECxpn5rvZimUvhp4VEc6NUgLvzTXyM240client # [5740908.050511] client data-mesher[209]: time=2026-08-14T10:05:34.103Z level=INFO msg="state exchange complete" peer=12D3KooWLyVZ4nzpb7YjjWECxpn5rvZimUvhp4VEc6NUgLvzTXyM timeout=5s241client # [5740908.050643] client data-mesher[209]: time=2026-08-14T10:05:34.103Z level=INFO msg="server started"242client # [5740908.050760] client data-mesher[209]: time=2026-08-14T10:05:34.103Z level=INFO msg="starting expired-file sweeper" interval=1m0s243client # [5740908.050851] client systemd[1]: Started data mesher daemon.244client # [5740908.053225] client systemd[1]: Starting Unbound recursive Domain Name Server...245server # [5740908.047515] server data-mesher[218]: time=2026-08-14T10:05:34.100Z level=INFO msg="performing state exchange with peers on join" count=1246server # [5740908.047933] server data-mesher[218]: time=2026-08-14T10:05:34.100Z level=DEBUG msg="initiating state exchange" peer=12D3KooWDn4eFckAAFwpc4jeyWvtMnV1EE9woKQ4oXT8Mk6j9wtu timeout=5s247server # [5740908.048455] server data-mesher[218]: time=2026-08-14T10:05:34.101Z level=INFO msg="merging remote state" peer=12D3KooWDn4eFckAAFwpc4jeyWvtMnV1EE9woKQ4oXT8Mk6j9wtu248server # [5740908.048455] server data-mesher[218]: time=2026-08-14T10:05:34.101Z level=INFO msg="state exchange complete" peer=12D3KooWDn4eFckAAFwpc4jeyWvtMnV1EE9woKQ4oXT8Mk6j9wtu timeout=5s249server # [5740908.048523] server data-mesher[218]: time=2026-08-14T10:05:34.101Z level=INFO msg="server started"250server # [5740908.048721] server data-mesher[218]: time=2026-08-14T10:05:34.101Z level=INFO msg="starting expired-file sweeper" interval=1m0s251server # [5740908.048919] server systemd[1]: Started data mesher daemon.252server # [5740908.050126] server data-mesher[218]: time=2026-08-14T10:05:34.103Z level=INFO msg="received state sync from peer" peer=12D3KooWDn4eFckAAFwpc4jeyWvtMnV1EE9woKQ4oXT8Mk6j9wtu253server # [5740908.050163] server data-mesher[218]: time=2026-08-14T10:05:34.103Z level=INFO msg="merging remote state" peer=12D3KooWDn4eFckAAFwpc4jeyWvtMnV1EE9woKQ4oXT8Mk6j9wtu254server # [5740908.050968] server systemd[1]: Starting Unbound recursive Domain Name Server...255client # [5740908.610474] client unbound-pre-start[272]: Root anchor updated!256client # [5740908.624844] client unbound-pre-start[276]: setup in directory /var/lib/unbound257server # [5740908.610336] server unbound-pre-start[281]: Root anchor updated!258server # [5740908.624098] server unbound-pre-start[285]: setup in directory /var/lib/unbound259server # [5740909.399264] server unbound-pre-start[294]: Certificate request self-signature ok260server # [5740909.399264] server unbound-pre-start[294]: subject=CN=unbound-control261server # [5740909.418399] server unbound-pre-start[285]: removing artifacts262server # [5740909.420716] server unbound-pre-start[285]: Setup success. Certificates created. Enable in unbound.conf file to use263client # [5740909.915232] client unbound-pre-start[285]: Certificate request self-signature ok264client # [5740909.915232] client unbound-pre-start[285]: subject=CN=unbound-control265client # [5740909.934454] client unbound-pre-start[276]: removing artifacts266client # [5740909.936297] client unbound-pre-start[276]: Setup success. Certificates created. Enable in unbound.conf file to use267server # [5740909.927958] server unbound[298]: [298:0] notice: init module 0: validator268server # [5740909.928083] server unbound[298]: [298:0] notice: init module 1: iterator269server # [5740909.933721] server unbound[298]: [298:0] info: start of service (unbound 1.25.2).270server # [5740909.933830] server systemd[1]: Started Unbound recursive Domain Name Server.271server # [5740909.934133] server systemd[1]: Reached target Multi-User System.272server # [5740909.934292] server systemd[1]: Reached target Host and Network Name Lookups.273server # [5740909.935639] server systemd[1]: Starting Reload unbound zone configuration...274server # [5740909.985358] server unbound[298]: [298:0] info: service stopped (unbound 1.25.2).275server # [5740909.985501] server unbound-control[302]: ok276server # [5740909.985697] server unbound[298]: [298:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting277server # [5740909.985702] server unbound[298]: [298:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0278server # [5740909.987111] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.279server # [5740909.987394] server unbound[298]: [298:0] notice: Restart of unbound 1.25.2.280server # [5740909.987405] server systemd[1]: Finished Reload unbound zone configuration.281server # [5740909.987834] server systemd[1]: Startup finished in 13.721s.282server # [5740909.988280] server unbound[298]: [298:0] notice: init module 0: validator283server # [5740909.988345] server unbound[298]: [298:0] notice: init module 1: iterator284server # [5740909.992879] server unbound[298]: [298:0] info: start of service (unbound 1.25.2).285server: (finished: waiting for unit unbound.service, in 14.67 seconds)286client: waiting for unit unbound.service287client: (finished: waiting for unit unbound.service, in 0.17 seconds)288server: waiting for unit data-mesher.service289server: (finished: waiting for unit data-mesher.service, in 0.02 seconds)290server: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1291server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1, in 0.03 seconds)292server: must succeed: data-mesher file update --network-id /nix/store/40p8y58cg486wd6r7qyl04f3r13yxw9h-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/cnames293server: (finished: must succeed: data-mesher file update --network-id /nix/store/40p8y58cg486wd6r7qyl04f3r13yxw9h-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)294??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.295 File "/nix/store/258dmf26bj4wx2idmzbn2vz4hzlmk8bh-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39296server: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test297??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.298 File "/nix/store/258dmf26bj4wx2idmzbn2vz4hzlmk8bh-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39299client # [5740910.438386] client unbound[290]: [290:0] notice: init module 0: validator300client # [5740910.438505] client unbound[290]: [290:0] notice: init module 1: iterator301client # [5740910.444141] client unbound[290]: [290:0] info: start of service (unbound 1.25.2).302client # [5740910.444254] client systemd[1]: Started Unbound recursive Domain Name Server.303client # [5740910.444576] client systemd[1]: Reached target Multi-User System.304client # [5740910.444738] client systemd[1]: Reached target Host and Network Name Lookups.305client # [5740910.501410] client systemd[1]: Starting Reload unbound zone configuration...306client # [5740910.513101] client unbound[290]: [290:0] info: service stopped (unbound 1.25.2).307client # [5740910.513456] client unbound-control[293]: ok308client # [5740910.513445] client unbound[290]: [290:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting309client # [5740910.513449] client unbound[290]: [290:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0310client # [5740910.514962] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.311client # [5740910.515157] client unbound[290]: [290:0] notice: Restart of unbound 1.25.2.312client # [5740910.515283] client systemd[1]: Finished Reload unbound zone configuration.313client # [5740910.515695] client systemd[1]: Startup finished in 14.262s.314client # [5740910.516047] client unbound[290]: [290:0] notice: init module 0: validator315client # [5740910.516112] client unbound[290]: [290:0] notice: init module 1: iterator316client # [5740910.520659] client unbound[290]: [290:0] info: start of service (unbound 1.25.2).317server # [5740910.672889] server systemd[1]: Starting Reload unbound zone configuration...318server # [5740910.684133] server data-mesher[218]: time=2026-08-14T10:05:36.737Z level=INFO msg=http_request uri=/files/dns/cnames status=204319server # [5740910.713270] server unbound-control[336]: ok320server # [5740910.713351] server unbound[298]: [298:0] info: service stopped (unbound 1.25.2).321server # [5740910.713793] server unbound[298]: [298:0] info: server stats for thread 0: 5 queries, 2 answers from cache, 3 recursions, 0 prefetch, 0 rejected by ip ratelimiting322server # [5740910.713799] server unbound[298]: [298:0] info: server stats for thread 0: requestlist max 2 avg 1.33333 exceeded 0 jostled 0323server # [5740910.715240] server unbound[298]: [298:0] notice: Restart of unbound 1.25.2.324server # [5740910.716289] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.325server # [5740910.716368] server unbound[298]: [298:0] notice: init module 0: validator326server # [5740910.716430] server unbound[298]: [298:0] notice: init module 1: iterator327server # [5740910.716452] server systemd[1]: Finished Reload unbound zone configuration.328server # [5740910.721697] server unbound[298]: [298:0] info: start of service (unbound 1.25.2).329server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test, in 1.05 seconds)330(finished: run the VM test script, in 15.98 seconds)331test script finished in 16.09s332cleanup333kill NspawnMachine (pid 52)334kill NspawnMachine (pid 53)335Container client terminated by signal KILL.336Container server terminated by signal KILL.337(finished: cleanup, in 0.43 seconds)