container-test-run-dm-dns
checks.aarch64-linux.dm-dns
· build #884
· raw
1build01: building 6j3g4yjmqk97svi2knc0wyzfvgx1xhgy-container-test-run-dm-dns.drv2Machine state will be reset. To keep it, pass --keep-machine-state3start all VLans4(finished: start all VLans, in 0.00 seconds)56Test will time out and terminate in 3600.0 seconds7run the VM test script8additionally exposed symbols:9 client, server,10 vlan1,11 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_ssh12start all VMs13client: systemd-nspawn running (pid 52)14client: Waiting for journal at /build/vm-state-client/var/log/journal...15server: systemd-nspawn running (pid 54)16server: Waiting for journal at /build/vm-state-server/var/log/journal...17(finished: start all VMs, in 0.00 seconds)18server: waiting for unit unbound.service19nixos-nspawn(server): TAP vde-tap1 not found; container will be isolated from VDE20nixos-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.21nixos-nspawn(client): TAP vde-tap1 not found; container will be isolated from VDE22nixos-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.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.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 server on /build/vm-state-server.26░ Spawning container client on /build/vm-state-client.27client # No journal files were found.28client # No journal boot entry found for the specified boot (+0).29server # No journal files were found.30server # No journal boot entry found for the specified boot (+0).31client # [2843445.027665] client systemd-journald[90]: Journal started32client # [2843445.027726] client systemd-journald[90]: Runtime Journal (/run/log/journal/4558d861623d47cebc9f1156967216fe) is 8M, max 2.5G, 2.4G free.33client # [2843445.036021] client systemd[1]: Finished Apply Kernel Variables.34client # [2843445.047966] client systemd[1]: Finished Create Static Device Nodes in /dev gracefully.35client # [2843445.060674] client systemd[1]: Starting Flush Journal to Persistent Storage...36client # [2843445.061449] client systemd[1]: Starting Network Name Resolution...37client # [2843445.062084] client systemd[1]: Starting Create Static Device Nodes in /dev...38client # [2843445.070162] client systemd-journald[90]: Time spent on flushing to /var/log/journal/4558d861623d47cebc9f1156967216fe is 1.300ms for 7 entries.39client # [2843445.070162] client systemd-journald[90]: System Journal (/var/log/journal/4558d861623d47cebc9f1156967216fe) is 8M, max 4G, 3.9G free.40client # [2843445.079825] client systemd[1]: Finished Create Static Device Nodes in /dev.41client # [2843445.080398] client systemd[1]: Reached target Preparation for Local File Systems.42client # [2843445.080511] client systemd[1]: Reached target Local File Systems.43client # [2843445.081361] client systemd[1]: Listening on Boot Loader Control Service Socket.44client # [2843445.081414] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container45client # [2843445.082344] client systemd[1]: Starting Save Transient machine-id to Disk...46client # [2843445.082380] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys47client # [2843445.082807] client systemd[1]: Finished Flush Journal to Persistent Storage.48client # [2843445.084379] client systemd[1]: Starting Create System Files and Directories...49client # [2843445.103548] client systemd-tmpfiles[143]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted50client # [2843445.103763] client systemd-tmpfiles[143]: fchmod() of /var/log/journal failed: Operation not permitted51client # [2843445.103909] client systemd-tmpfiles[143]: fchmod() of /var/log/journal/4558d861623d47cebc9f1156967216fe failed: Operation not permitted52client # [2843445.104236] client systemd-tmpfiles[143]: fchmod() of /run/log/journal failed: Operation not permitted53client # [2843445.105588] client systemd[1]: Finished Create System Files and Directories.54client # [2843445.106744] client systemd[1]: Starting Rebuild Journal Catalog...55client # [2843445.107564] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...56client # [2843445.121128] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.57client # [2843445.125692] client systemd[1]: Finished Save Transient machine-id to Disk.58client # [2843445.130542] client systemd[1]: Finished Rebuild Journal Catalog.59client # [2843445.131812] client systemd[1]: Starting Update is Completed...60client # [2843445.144260] client systemd[1]: Finished Update is Completed.61client # [2843445.201871] client systemd[1]: Finished Firewall.62client # [2843445.202068] client systemd[1]: Reached target Preparation for Network.63client # [2843445.202354] client systemd[1]: Listening on Network Management Resolve Hook Socket.64client # [2843445.203690] client systemd[1]: Starting Network Management...65client # [2843445.839695] client systemd-networkd[208]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted66client # [2843445.839785] client systemd-networkd[208]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted67client # [2843445.848818] client systemd-networkd[208]: /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.68client # [2843445.848988] client systemd-networkd[208]: /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.69client # [2843445.849137] client systemd-networkd[208]: lo: Link UP70client # [2843445.849140] client systemd-networkd[208]: lo: Gained carrier71client # [2843445.849326] client systemd-networkd[208]: eth1: Configuring with /etc/systemd/network/40-eth1.network.72client # [2843445.849752] client systemd[1]: Started Network Management.73client # [2843445.849757] client systemd-networkd[208]: eth1: Link UP74client # [2843445.850073] client systemd-networkd[208]: eth1: Gained carrier75client # [2843445.880550] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd...76client # [2843445.897774] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd.77client # [2843446.018499] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.78server # [2843445.017361] server systemd-journald[99]: Journal started79server # [2843445.017424] server systemd-journald[99]: Runtime Journal (/run/log/journal/f6048b97ca05468fb10e69981201fd07) is 8M, max 2.5G, 2.4G free.80server # [2843445.037019] server systemd[1]: Finished Apply Kernel Variables.81server # [2843445.052023] server systemd[1]: Finished Create Static Device Nodes in /dev gracefully.82server # [2843445.068264] server systemd[1]: Starting Flush Journal to Persistent Storage...83server # [2843445.069111] server systemd[1]: Starting Network Name Resolution...84server # [2843445.069772] server systemd[1]: Starting Create Static Device Nodes in /dev...85server # [2843445.079853] server systemd-journald[99]: Time spent on flushing to /var/log/journal/f6048b97ca05468fb10e69981201fd07 is 1.318ms for 7 entries.86server # [2843445.079853] server systemd-journald[99]: System Journal (/var/log/journal/f6048b97ca05468fb10e69981201fd07) is 8M, max 4G, 3.9G free.87server # [2843445.096963] server systemd[1]: Finished Flush Journal to Persistent Storage.88server # [2843445.097279] server systemd[1]: Finished Create Static Device Nodes in /dev.89server # [2843445.098391] server systemd[1]: Reached target Preparation for Local File Systems.90server # [2843445.098493] server systemd[1]: Reached target Local File Systems.91server # [2843445.099309] server systemd[1]: Listening on Boot Loader Control Service Socket.92server # [2843445.099354] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container93server # [2843445.100168] server systemd[1]: Starting Save Transient machine-id to Disk...94server # [2843445.100807] server systemd[1]: Starting Create System Files and Directories...95server # [2843445.100835] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys96server # [2843445.117603] server systemd-tmpfiles[163]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted97server # [2843445.117815] server systemd-tmpfiles[163]: fchmod() of /var/log/journal failed: Operation not permitted98server # [2843445.117963] server systemd-tmpfiles[163]: fchmod() of /var/log/journal/f6048b97ca05468fb10e69981201fd07 failed: Operation not permitted99server # [2843445.118181] server systemd-tmpfiles[163]: fchmod() of /run/log/journal failed: Operation not permitted100server # [2843445.119590] server systemd[1]: Finished Create System Files and Directories.101server # [2843445.121158] server systemd[1]: Starting Rebuild Journal Catalog...102server # [2843445.121904] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...103server # [2843445.125693] server systemd[1]: Finished Save Transient machine-id to Disk.104server # [2843445.135841] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.105server # [2843445.145074] server systemd[1]: Finished Rebuild Journal Catalog.106server # [2843445.146237] server systemd[1]: Starting Update is Completed...107server # [2843445.157927] server systemd[1]: Finished Update is Completed.108server # [2843445.194013] server systemd[1]: Finished Firewall.109server # [2843445.194183] server systemd[1]: Reached target Preparation for Network.110server # [2843445.194426] server systemd[1]: Listening on Network Management Resolve Hook Socket.111server # [2843445.195651] server systemd[1]: Starting Network Management...112server # [2843445.833881] server systemd-networkd[217]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted113server # [2843445.833969] server systemd-networkd[217]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted114server # [2843445.843052] server systemd-networkd[217]: /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.115server # [2843445.843216] server systemd-networkd[217]: /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.116server # [2843445.843368] server systemd-networkd[217]: lo: Link UP117server # [2843445.843373] server systemd-networkd[217]: lo: Gained carrier118server # [2843445.843568] server systemd-networkd[217]: eth1: Configuring with /etc/systemd/network/40-eth1.network.119server # [2843445.843920] server systemd[1]: Started Network Management.120server # [2843445.844030] server systemd-networkd[217]: eth1: Link UP121server # [2843445.844363] server systemd-networkd[217]: eth1: Gained carrier122server # [2843445.845122] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...123server # [2843445.890416] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.124server # [2843446.018139] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.125server # [2843446.184138] server systemd-resolved[142]: Positive Trust Anchors:126server # [2843446.184149] server systemd-resolved[142]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d127server # [2843446.184152] server systemd-resolved[142]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16128server # [2843446.184185] server systemd-resolved[142]: 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 test129server # [2843446.204316] server systemd-resolved[142]: Using system hostname 'server'.130server # [2843446.205670] server systemd[1]: Started Network Name Resolution.131server # [2843446.205796] server systemd[1]: Reached target Network.132server # [2843446.205923] server systemd[1]: Reached target System Initialization.133server # [2843446.206087] server systemd[1]: Started Watch for zone file changes.134server # [2843446.206140] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container135server # [2843446.206187] server systemd[1]: Started Daily Cleanup of Temporary Directories.136server # [2843446.206223] server systemd[1]: Reached target Path Units.137server # [2843446.206290] server systemd[1]: Reached target Timer Units.138server # [2843446.206507] server systemd[1]: Listening on D-Bus System Message Bus Socket.139server # [2843446.206711] server systemd[1]: Listening on Nix Daemon Socket.140server # [2843446.206930] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.141server # [2843446.206980] server systemd[1]: Reached target Socket Units.142server # [2843446.207055] server systemd[1]: Reached target Basic System.143server # [2843446.244544] server systemd[1]: Starting data mesher daemon...144server # [2843446.246031] server systemd[1]: Starting Import lastlog data into lastlog2 database...145server # [2843446.247418] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...146server # [2843446.249494] server systemd[1]: Starting D-Bus System Message Bus...147server # [2843446.270025] server systemd[1]: Finished Import lastlog data into lastlog2 database.148server # [2843446.446698] server systemd[1]: Started Name Service Cache Daemon (nsncd).149server # [2843446.446815] server systemd[1]: Reached target User and Group Name Lookups.150client # [2843446.167607] client systemd-resolved[125]: Positive Trust Anchors:151client # [2843446.167619] client systemd-resolved[125]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d152client # [2843446.167623] client systemd-resolved[125]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16153client # [2843446.167657] client systemd-resolved[125]: 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 test154client # [2843446.188542] client systemd-resolved[125]: Using system hostname 'client'.155client # [2843446.189882] client systemd[1]: Started Network Name Resolution.156client # [2843446.190013] client systemd[1]: Reached target Network.157client # [2843446.190143] client systemd[1]: Reached target System Initialization.158client # [2843446.190301] client systemd[1]: Started Watch for zone file changes.159client # [2843446.190354] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container160client # [2843446.190403] client systemd[1]: Started Daily Cleanup of Temporary Directories.161client # [2843446.190438] client systemd[1]: Reached target Path Units.162client # [2843446.190504] client systemd[1]: Reached target Timer Units.163client # [2843446.190741] client systemd[1]: Listening on D-Bus System Message Bus Socket.164client # [2843446.190945] client systemd[1]: Listening on Nix Daemon Socket.165client # [2843446.191161] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.166client # [2843446.191204] client systemd[1]: Reached target Socket Units.167client # [2843446.191277] client systemd[1]: Reached target Basic System.168client # [2843446.193591] client systemd[1]: Starting data mesher daemon...169client # [2843446.194883] client systemd[1]: Starting Import lastlog data into lastlog2 database...170client # [2843446.196335] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...171client # [2843446.198600] client systemd[1]: Starting D-Bus System Message Bus...172client # [2843446.264911] client systemd[1]: Finished Import lastlog data into lastlog2 database.173server # [2843446.447045] server nsncd[224]: Oct 07 05:17:46.432 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"174server # [2843446.449056] server systemd[1]: Starting User Login Management...175server # [2843446.450659] server systemd[1]: Starting Permit User Sessions...176server # [2843446.508106] server systemd[1]: Finished Permit User Sessions.177server # [2843446.509434] server systemd[1]: Started Console Getty.178server # [2843446.509481] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0179server # [2843446.509511] server systemd[1]: Reached target Login Prompts.180server # [2843446.598895] server dbus-broker-launch[225]: Looking up NSS user entry for 'systemd-timesync'...181server # [2843446.600275] server dbus-broker-launch[225]: NSS returned no entry for 'systemd-timesync'182server # [2843446.600275] server dbus-broker-launch[225]: Invalid user-name in /nix/store/z6bc5qxzypiwvkwcjrz4iygfhwknib9q-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"183server # [2843446.600941] server systemd[1]: Started D-Bus System Message Bus.184server # [2843446.609517] server dbus-broker-launch[225]: Ready185client # [2843446.487450] client systemd[1]: Started Name Service Cache Daemon (nsncd).186client # [2843446.487561] client systemd[1]: Reached target User and Group Name Lookups.187client # [2843446.487696] client nsncd[215]: Oct 07 05:17:46.473 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"188client # [2843446.500503] client systemd[1]: Starting User Login Management...189client # [2843446.502001] client systemd[1]: Starting Permit User Sessions...190client # [2843446.514152] client systemd[1]: Finished Permit User Sessions.191client # [2843446.515761] client systemd[1]: Started Console Getty.192client # [2843446.515836] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0193client # [2843446.515876] client systemd[1]: Reached target Login Prompts.194client # [2843446.633841] client dbus-broker-launch[216]: Looking up NSS user entry for 'systemd-timesync'...195client # [2843446.635116] client dbus-broker-launch[216]: NSS returned no entry for 'systemd-timesync'196client # [2843446.635116] client dbus-broker-launch[216]: Invalid user-name in /nix/store/hw80ksg4plnak3bz030j3qgij13a17gf-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"197client # [2843446.635554] client systemd[1]: Started D-Bus System Message Bus.198client # [2843446.643046] client dbus-broker-launch[216]: Ready199client # [2843446.980975] client data-mesher[213]: time=2026-10-07T05:17:46.966Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]200client # [2843446.982051] client data-mesher[213]: time=2026-10-07T05:17:46.967Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4: [/dns/client.test/tcp/7946]} {12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4201client # [2843446.982051] client data-mesher[213]: time=2026-10-07T05:17:46.967Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml202client # [2843446.985529] client data-mesher[213]: time=2026-10-07T05:17:46.971Z level=INFO msg="checking file integrity"203client # [2843446.985643] client data-mesher[213]: time=2026-10-07T05:17:46.971Z level=INFO msg="file integrity check complete"204client # [2843446.989511] client data-mesher[213]: time=2026-10-07T05:17:46.975Z level=INFO msg="libp2p host created" peer_id=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4 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]"205client # [2843446.989592] client data-mesher[213]: time=2026-10-07T05:17:46.975Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name206client # [2843446.989592] client data-mesher[213]: time=2026-10-07T05:17:46.975Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name207client # [2843446.989592] client data-mesher[213]: time=2026-10-07T05:17:46.975Z level=INFO msg="registered HTTP route" method=GET path=/files208client # [2843446.989592] client data-mesher[213]: time=2026-10-07T05:17:46.975Z level=INFO msg="starting server"209client # [2843446.989777] client data-mesher[213]: time=2026-10-07T05:17:46.975Z level=INFO msg="waiting for DHT to populate" delay=10s210client # [2843446.989777] client data-mesher[213]: time=2026-10-07T05:17:46.975Z level=INFO msg="HTTP server listening" address=[::1]:7331211client # [2843446.989777] client data-mesher[213]: time=2026-10-07T05:17:46.975Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331212client # [2843446.998504] client data-mesher[213]: time=2026-10-07T05:17:46.984Z level=INFO msg="peer connected" peer_id=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ remote_addr=/ip4/192.168.1.2/tcp/7946213client # [2843447.023228] client data-mesher[213]: time=2026-10-07T05:17:47.009Z level=INFO msg="peer connected" peer_id=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ remote_addr=/ip4/192.168.1.2/tcp/7946214server # [2843446.984536] server data-mesher[222]: time=2026-10-07T05:17:46.970Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]215server # [2843446.985586] server data-mesher[222]: time=2026-10-07T05:17:46.971Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4: [/dns/client.test/tcp/7946]} {12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ216server # [2843446.985586] server data-mesher[222]: time=2026-10-07T05:17:46.971Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml217server # [2843446.988974] server data-mesher[222]: time=2026-10-07T05:17:46.974Z level=INFO msg="checking file integrity"218server # [2843446.988974] server data-mesher[222]: time=2026-10-07T05:17:46.974Z level=INFO msg="file integrity check complete"219server # [2843446.993134] server data-mesher[222]: time=2026-10-07T05:17:46.978Z level=INFO msg="libp2p host created" peer_id=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ 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]"220server # [2843446.993239] server data-mesher[222]: time=2026-10-07T05:17:46.978Z level=INFO msg="registered HTTP route" method=GET path=/files221server # [2843446.993239] server data-mesher[222]: time=2026-10-07T05:17:46.978Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name222server # [2843446.993239] server data-mesher[222]: time=2026-10-07T05:17:46.978Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name223server # [2843446.993239] server data-mesher[222]: time=2026-10-07T05:17:46.979Z level=INFO msg="starting server"224server # [2843446.993357] server data-mesher[222]: time=2026-10-07T05:17:46.979Z level=INFO msg="waiting for DHT to populate" delay=10s225server # [2843446.993387] server data-mesher[222]: time=2026-10-07T05:17:46.979Z level=INFO msg="HTTP server listening" address=[::1]:7331226server # [2843446.993419] server data-mesher[222]: time=2026-10-07T05:17:46.979Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331227server # [2843446.997584] server data-mesher[222]: time=2026-10-07T05:17:46.983Z level=INFO msg="peer connected" peer_id=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4 remote_addr=/ip4/192.168.1.1/tcp/7946228server # [2843447.024235] server data-mesher[222]: time=2026-10-07T05:17:47.010Z level=INFO msg="peer connected" peer_id=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4 remote_addr=/ip4/192.168.1.1/tcp/36286229server # [2843447.269936] server systemd-logind[242]: New seat seat0.230server # [2843447.270134] server systemd[1]: Started User Login Management.231server # [2843447.296801] server systemd[1]: Starting linger-users.service...232server # [2843447.310407] server systemd[1]: linger-users.service: Deactivated successfully.233server # [2843447.310722] server systemd[1]: Finished linger-users.service.234client # [2843447.255308] client systemd-logind[233]: New seat seat0.235client # [2843447.255535] client systemd[1]: Started User Login Management.236client # [2843447.257622] client systemd[1]: Starting linger-users.service...237client # [2843447.306044] client systemd[1]: linger-users.service: Deactivated successfully.238client # [2843447.306208] client systemd[1]: Finished linger-users.service.239server # [2843447.584134] server systemd-networkd[217]: eth1: Gained IPv6LL240client # [2843447.808125] client systemd-networkd[208]: eth1: Gained IPv6LL241server: still waiting for container 'server' to reach ready state...242server # [2843456.991334] server data-mesher[222]: time=2026-10-07T05:17:56.977Z level=INFO msg="received state sync from peer" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4243server # [2843456.991334] server data-mesher[222]: time=2026-10-07T05:17:56.977Z level=INFO msg="merging remote state" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4244server # [2843456.993968] server data-mesher[222]: time=2026-10-07T05:17:56.979Z level=INFO msg="performing state exchange with peers on join" count=1245server # [2843456.993968] server data-mesher[222]: time=2026-10-07T05:17:56.979Z level=DEBUG msg="initiating state exchange" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4 timeout=5s246server # [2843456.994702] server data-mesher[222]: time=2026-10-07T05:17:56.980Z level=INFO msg="merging remote state" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4247server # [2843456.994702] server data-mesher[222]: time=2026-10-07T05:17:56.980Z level=INFO msg="state exchange complete" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4 timeout=5s248server # [2843456.994818] server data-mesher[222]: time=2026-10-07T05:17:56.980Z level=INFO msg="server started"249server # [2843456.994874] server data-mesher[222]: time=2026-10-07T05:17:56.980Z level=INFO msg="starting expired-file sweeper" interval=1m0s250server # [2843456.995013] server systemd[1]: Started data mesher daemon.251server # [2843456.997318] server systemd[1]: Starting Unbound recursive Domain Name Server...252client # [2843456.990565] client data-mesher[213]: time=2026-10-07T05:17:56.976Z level=INFO msg="performing state exchange with peers on join" count=1253client # [2843456.990565] client data-mesher[213]: time=2026-10-07T05:17:56.976Z level=DEBUG msg="initiating state exchange" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ timeout=5s254client # [2843456.991555] client data-mesher[213]: time=2026-10-07T05:17:56.977Z level=INFO msg="merging remote state" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ255client # [2843456.991555] client data-mesher[213]: time=2026-10-07T05:17:56.977Z level=INFO msg="state exchange complete" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ timeout=5s256client # [2843456.991682] client data-mesher[213]: time=2026-10-07T05:17:56.977Z level=INFO msg="server started"257client # [2843456.991825] client data-mesher[213]: time=2026-10-07T05:17:56.977Z level=INFO msg="starting expired-file sweeper" interval=1m0s258client # [2843456.991941] client systemd[1]: Started data mesher daemon.259client # [2843456.994463] client data-mesher[213]: time=2026-10-07T05:17:56.980Z level=INFO msg="received state sync from peer" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ260client # [2843456.994563] client data-mesher[213]: time=2026-10-07T05:17:56.980Z level=INFO msg="merging remote state" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ261client # [2843456.994499] client systemd[1]: Starting Unbound recursive Domain Name Server...262server # [2843457.904231] server unbound-pre-start[285]: Root anchor updated!263server # [2843457.919454] server unbound-pre-start[289]: setup in directory /var/lib/unbound264client # [2843457.902924] client unbound-pre-start[277]: Root anchor updated!265client # [2843457.919396] client unbound-pre-start[281]: setup in directory /var/lib/unbound266client # [2843459.132989] client unbound-pre-start[290]: Certificate request self-signature ok267client # [2843459.132989] client unbound-pre-start[290]: subject=CN=unbound-control268client # [2843459.155584] client unbound-pre-start[281]: removing artifacts269client # [2843459.157766] client unbound-pre-start[281]: Setup success. Certificates created. Enable in unbound.conf file to use270server # [2843459.885702] server unbound-pre-start[298]: Certificate request self-signature ok271server # [2843459.885702] server unbound-pre-start[298]: subject=CN=unbound-control272server # [2843459.905743] server unbound-pre-start[289]: removing artifacts273server # [2843459.907519] server unbound-pre-start[289]: Setup success. Certificates created. Enable in unbound.conf file to use274client # [2843460.139251] client unbound[295]: [295:0] notice: init module 0: validator275client # [2843460.139325] client unbound[295]: [295:0] notice: init module 1: iterator276client # [2843460.143640] client unbound[295]: [295:0] info: start of service (unbound 1.26.1).277client # [2843460.143796] client systemd[1]: Started Unbound recursive Domain Name Server.278client # [2843460.144353] client systemd[1]: Reached target Multi-User System.279client # [2843460.144647] client systemd[1]: Reached target Host and Network Name Lookups.280client # [2843460.146638] client systemd[1]: Starting Reload unbound zone configuration...281client # [2843460.196177] client unbound[295]: [295:0] info: service stopped (unbound 1.26.1).282client # [2843460.196661] client unbound[295]: [295:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting283client # [2843460.197173] client unbound-control[298]: ok284client # [2843460.196667] client unbound[295]: [295:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0285client # [2843460.197974] client unbound[295]: [295:0] notice: Restart of unbound 1.26.1.286client # [2843460.198225] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.287client # [2843460.198545] client systemd[1]: Finished Reload unbound zone configuration.288client # [2843460.198993] client systemd[1]: Startup finished in 15.624s.289client # [2843460.199004] client unbound[295]: [295:0] notice: init module 0: validator290client # [2843460.199074] client unbound[295]: [295:0] notice: init module 1: iterator291client # [2843460.203580] client unbound[295]: [295:0] info: start of service (unbound 1.26.1).292server # [2843460.843371] server unbound[303]: [303:0] notice: init module 0: validator293server # [2843460.843450] server unbound[303]: [303:0] notice: init module 1: iterator294server # [2843460.847645] server unbound[303]: [303:0] info: start of service (unbound 1.26.1).295server # [2843460.847811] server systemd[1]: Started Unbound recursive Domain Name Server.296server # [2843460.848357] server systemd[1]: Reached target Multi-User System.297server # [2843460.848630] server systemd[1]: Reached target Host and Network Name Lookups.298server # [2843460.850419] server systemd[1]: Starting Reload unbound zone configuration...299server # [2843460.888811] server unbound[303]: [303:0] info: service stopped (unbound 1.26.1).300server # [2843460.889078] server unbound[303]: [303:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting301server # [2843460.889084] server unbound[303]: [303:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0302server # [2843460.889236] server unbound-control[306]: ok303server # [2843460.889946] server unbound[303]: [303:0] notice: Restart of unbound 1.26.1.304server # [2843460.890665] server unbound[303]: [303:0] notice: init module 0: validator305server # [2843460.890670] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.306server # [2843460.890721] server unbound[303]: [303:0] notice: init module 1: iterator307server # [2843460.890976] server systemd[1]: Finished Reload unbound zone configuration.308server # [2843460.891516] server systemd[1]: Startup finished in 16.301s.309server # [2843460.894531] server unbound[303]: [303:0] info: start of service (unbound 1.26.1).310server: (finished: waiting for unit unbound.service, in 17.18 seconds)311client: waiting for unit unbound.service312client: (finished: waiting for unit unbound.service, in 0.02 seconds)313server: waiting for unit data-mesher.service314server: (finished: waiting for unit data-mesher.service, in 0.02 seconds)315server: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1316server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1, in 0.03 seconds)317server: must succeed: data-mesher file update --network-id /nix/store/0a5mpxfya7m0p21561xg0bxln21lryjy-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/cnames318server: (finished: must succeed: data-mesher file update --network-id /nix/store/0a5mpxfya7m0p21561xg0bxln21lryjy-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.03 seconds)319??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.320 File "/nix/store/x4i03lhka9aiwxswmbhjfzzbl77nlxmj-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39321server: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test322??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.323 File "/nix/store/x4i03lhka9aiwxswmbhjfzzbl77nlxmj-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39324server # [2843461.306433] server systemd[1]: Starting Reload unbound zone configuration...325server # [2843461.309574] server data-mesher[222]: time=2026-10-07T05:18:01.295Z level=INFO msg=http_request uri=/files/dns/cnames status=204326server # [2843461.340826] server unbound[303]: [303:0] info: service stopped (unbound 1.26.1).327server # [2843461.341143] server unbound-control[342]: ok328server # [2843461.341258] server unbound[303]: [303:0] info: server stats for thread 0: 5 queries, 2 answers from cache, 3 recursions, 0 prefetch, 0 rejected by ip ratelimiting329server # [2843461.341263] server unbound[303]: [303:0] info: server stats for thread 0: requestlist max 2 avg 1.33333 exceeded 0 jostled 0330server # [2843461.342328] server unbound[303]: [303:0] notice: Restart of unbound 1.26.1.331server # [2843461.342759] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.332server # [2843461.343099] server systemd[1]: Finished Reload unbound zone configuration.333server # [2843461.343129] server unbound[303]: [303:0] notice: init module 0: validator334server # [2843461.343184] server unbound[303]: [303:0] notice: init module 1: iterator335server # [2843461.347201] server unbound[303]: [303:0] info: start of service (unbound 1.26.1).336server # [2843461.992843] server data-mesher[222]: time=2026-10-07T05:18:01.978Z level=INFO msg="received state sync from peer" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4337server # [2843461.992843] server data-mesher[222]: time=2026-10-07T05:18:01.978Z level=INFO msg="merging remote state" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4338server # [2843461.993969] server data-mesher[222]: time=2026-10-07T05:18:01.979Z level=INFO msg="received file request" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4 network="SsPnUh43hHu+zIo1q0DQhN4pLD7iW5mx/wl6geJG7vo=" name=dns/cnames339server # [2843461.994949] server data-mesher[222]: time=2026-10-07T05:18:01.980Z level=DEBUG msg="attempting push/pull" peer_count=1340server # [2843461.995023] server data-mesher[222]: time=2026-10-07T05:18:01.980Z level=DEBUG msg="initiating state exchange" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4 timeout=5s341server # [2843461.997130] server data-mesher[222]: time=2026-10-07T05:18:01.982Z level=INFO msg="merging remote state" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4342server # [2843461.997130] server data-mesher[222]: time=2026-10-07T05:18:01.982Z level=INFO msg="state exchange complete" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4 timeout=5s343server # [2843461.997274] server data-mesher[222]: time=2026-10-07T05:18:01.983Z level=DEBUG msg="push/pull successful" interval=5s344client # [2843461.992188] client data-mesher[213]: time=2026-10-07T05:18:01.977Z level=DEBUG msg="attempting push/pull" peer_count=1345client # [2843461.992188] client data-mesher[213]: time=2026-10-07T05:18:01.978Z level=DEBUG msg="initiating state exchange" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ timeout=5s346client # [2843461.993309] client data-mesher[213]: time=2026-10-07T05:18:01.979Z level=INFO msg="merging remote state" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ347client # [2843461.993400] client data-mesher[213]: time=2026-10-07T05:18:01.979Z level=DEBUG msg="new file detected" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ name=dns/cnames name=dns/cnames348client # [2843461.993400] client data-mesher[213]: time=2026-10-07T05:18:01.979Z level=INFO msg="state exchange complete" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ timeout=5s349server # [2843461.997394] server data-mesher[222]: time=2026-10-07T05:18:01.983Z level=INFO msg="file transfer complete" peer=12D3KooWEMqCq2mHhk3vBsYYQ9Rh6pG3p5xgG1vwrqUgGDAEiFT4 network="SsPnUh43hHu+zIo1q0DQhN4pLD7iW5mx/wl6geJG7vo=" name=dns/cnames350client # [2843461.993400] client data-mesher[213]: time=2026-10-07T05:18:01.979Z level=DEBUG msg="push/pull successful" interval=5s351client # [2843461.993547] client data-mesher[213]: time=2026-10-07T05:18:01.979Z level=INFO msg="scheduling file download" name=dns/cnames352client # [2843461.993547] client data-mesher[213]: time=2026-10-07T05:18:01.979Z level=INFO msg="downloading file" name=dns/cnames signed_at="2026-10-07 05:18:01.286 +0000 UTC" signed_by="9Y0jWyLbOkydLfnHi/etyd277lcgg+7vigYaum+aaFY=" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ353client # [2843461.996137] client data-mesher[213]: time=2026-10-07T05:18:01.981Z level=INFO msg="received state sync from peer" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ354client # [2843461.996137] client data-mesher[213]: time=2026-10-07T05:18:01.981Z level=INFO msg="merging remote state" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ355client # [2843461.996269] client data-mesher[213]: time=2026-10-07T05:18:01.982Z level=DEBUG msg="new file detected" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ name=dns/cnames name=dns/cnames356client # [2843462.002311] client systemd[1]: Starting Reload unbound zone configuration...357client # [2843462.003426] client data-mesher[213]: time=2026-10-07T05:18:01.989Z level=INFO msg="download complete" name=dns/cnames signed_at="2026-10-07 05:18:01.286 +0000 UTC" signed_by="9Y0jWyLbOkydLfnHi/etyd277lcgg+7vigYaum+aaFY=" peer=12D3KooWD9g32Bfy6uzDKN3nr9N2ftTopWsLXXybGKvqZEnwgACJ written=true elapsed=9.937895ms358client # [2843462.045225] client unbound[295]: [295:0] info: service stopped (unbound 1.26.1).359client # [2843462.045694] client unbound-control[302]: ok360client # [2843462.045865] client unbound[295]: [295:0] info: server stats for thread 0: 5 queries, 0 answers from cache, 5 recursions, 0 prefetch, 0 rejected by ip ratelimiting361client # [2843462.045874] client unbound[295]: [295:0] info: server stats for thread 0: requestlist max 2 avg 1.6 exceeded 0 jostled 0362client # [2843462.047010] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.363client # [2843462.047335] client systemd[1]: Finished Reload unbound zone configuration.364client # [2843462.047669] client unbound[295]: [295:0] notice: Restart of unbound 1.26.1.365client # [2843462.049319] client unbound[295]: [295:0] notice: init module 0: validator366client # [2843462.049427] client unbound[295]: [295:0] notice: init module 1: iterator367client # [2843462.058882] client unbound[295]: [295:0] info: start of service (unbound 1.26.1).368server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test, in 1.05 seconds)369(finished: run the VM test script, in 18.34 seconds)370test script finished in 18.39s371cleanup372kill NspawnMachine (pid 52)373kill NspawnMachine (pid 54)374Container client terminated by signal KILL.375Container server terminated by signal KILL.376(finished: cleanup, in 0.33 seconds)