container-test-run-dm-dns
checks.aarch64-linux.dm-dns
· build #612
· 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 # No journal files were found.27server # No journal files were found.28client # No journal boot entry found for the specified boot (+0).29server # No journal boot entry found for the specified boot (+0).30client # [423679.559501] client systemd-journald[86]: Journal started31client # [423679.559549] client systemd-journald[86]: Runtime Journal (/run/log/journal/efe634b8367b4f75a782c67eb4fd5d1b) is 8M, max 2.5G, 2.4G free.32client # [423679.560848] client systemd[1]: Finished Apply Kernel Variables.33client # [423679.568944] client systemd[1]: Finished Create Static Device Nodes in /dev gracefully.34client # [423679.579235] client systemd[1]: Starting Flush Journal to Persistent Storage...35client # [423679.580179] client systemd[1]: Starting Network Name Resolution...36client # [423679.580801] client systemd[1]: Starting Create Static Device Nodes in /dev...37client # [423679.590246] client systemd-journald[86]: Time spent on flushing to /var/log/journal/efe634b8367b4f75a782c67eb4fd5d1b is 2.245ms for 7 entries.38client # [423679.590246] client systemd-journald[86]: System Journal (/var/log/journal/efe634b8367b4f75a782c67eb4fd5d1b) is 8M, max 4G, 3.9G free.39client # [423679.597371] client systemd[1]: Finished Create Static Device Nodes in /dev.40client # [423679.597614] client systemd[1]: Reached target Preparation for Local File Systems.41server # [423679.566764] server systemd-journald[96]: Journal started42server # [423679.566833] server systemd-journald[96]: Runtime Journal (/run/log/journal/d2cd5fe5ac934737ac9c12b7a353a11d) is 8M, max 2.5G, 2.4G free.43server # [423679.568890] server systemd[1]: Finished Create Static Device Nodes in /dev gracefully.44server # [423679.578592] server systemd[1]: Starting Flush Journal to Persistent Storage...45client # [423679.597700] client systemd[1]: Reached target Local File Systems.46server # [423679.579725] server systemd[1]: Starting Network Name Resolution...47client # [423679.598421] client systemd[1]: Listening on Boot Loader Control Service Socket.48server # [423679.580487] server systemd[1]: Starting Create Static Device Nodes in /dev...49client # [423679.598464] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container50client # [423679.599465] client systemd[1]: Starting Save Transient machine-id to Disk...51client # [423679.599501] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys52client # [423679.629165] client systemd[1]: Finished Flush Journal to Persistent Storage.53client # [423679.630256] client systemd[1]: Starting Create System Files and Directories...54client # [423679.645436] client systemd-tmpfiles[138]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted55client # [423679.645614] client systemd-tmpfiles[138]: fchmod() of /var/log/journal failed: Operation not permitted56client # [423679.645736] client systemd-tmpfiles[138]: fchmod() of /var/log/journal/efe634b8367b4f75a782c67eb4fd5d1b failed: Operation not permitted57client # [423679.645923] client systemd-tmpfiles[138]: fchmod() of /run/log/journal failed: Operation not permitted58client # [423679.647265] client systemd[1]: Finished Create System Files and Directories.59client # [423679.648311] client systemd[1]: Starting Rebuild Journal Catalog...60client # [423679.648964] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...61client # [423679.660738] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.62client # [423679.670649] client systemd[1]: Finished Rebuild Journal Catalog.63server # [423679.590082] server systemd-journald[96]: Time spent on flushing to /var/log/journal/d2cd5fe5ac934737ac9c12b7a353a11d is 1.571ms for 6 entries.64server # [423679.590082] server systemd-journald[96]: System Journal (/var/log/journal/d2cd5fe5ac934737ac9c12b7a353a11d) is 8M, max 4G, 3.9G free.65server # [423679.597317] server systemd[1]: Finished Create Static Device Nodes in /dev.66server # [423679.597566] server systemd[1]: Reached target Preparation for Local File Systems.67server # [423679.597650] server systemd[1]: Reached target Local File Systems.68server # [423679.598384] server systemd[1]: Listening on Boot Loader Control Service Socket.69server # [423679.598430] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container70server # [423679.599340] server systemd[1]: Starting Save Transient machine-id to Disk...71server # [423679.599378] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys72server # [423679.618228] server systemd[1]: Finished Flush Journal to Persistent Storage.73server # [423679.619718] server systemd[1]: Starting Create System Files and Directories...74server # [423679.637604] server systemd-tmpfiles[144]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted75server # [423679.637784] server systemd-tmpfiles[144]: fchmod() of /var/log/journal failed: Operation not permitted76server # [423679.637909] server systemd-tmpfiles[144]: fchmod() of /var/log/journal/d2cd5fe5ac934737ac9c12b7a353a11d failed: Operation not permitted77server # [423679.638089] server systemd-tmpfiles[144]: fchmod() of /run/log/journal failed: Operation not permitted78server # [423679.639512] server systemd[1]: Finished Create System Files and Directories.79server # [423679.640650] server systemd[1]: Starting Rebuild Journal Catalog...80server # [423679.641405] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...81client # [423679.671674] client systemd[1]: Starting Update is Completed...82server # [423679.655599] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.83server # [423679.660563] server systemd[1]: Finished Rebuild Journal Catalog.84server # [423679.662238] server systemd[1]: Starting Update is Completed...85server # [423679.671598] server systemd[1]: Finished Update is Completed.86server # [423679.727298] server systemd[1]: Finished Firewall.87server # [423679.727485] server systemd[1]: Reached target Preparation for Network.88server # [423679.727750] server systemd[1]: Listening on Network Management Resolve Hook Socket.89server # [423679.728984] server systemd[1]: Starting Network Management...90server # [423680.140975] server systemd-networkd[213]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted91server # [423680.141097] server systemd-networkd[213]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted92server # [423680.147505] 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.93server # [423680.147671] 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.94server # [423680.147842] server systemd-networkd[213]: lo: Link UP95server # [423680.147846] server systemd-networkd[213]: lo: Gained carrier96server # [423680.148042] server systemd-networkd[213]: eth1: Configuring with /etc/systemd/network/40-eth1.network.97server # [423680.148440] server systemd[1]: Started Network Management.98server # [423680.148616] server systemd-networkd[213]: eth1: Link UP99server # [423680.149007] server systemd-networkd[213]: eth1: Gained carrier100server # [423680.149460] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...101server # [423680.190021] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.102server # [423680.214309] server systemd-resolved[119]: Positive Trust Anchors:103server # [423680.214320] server systemd-resolved[119]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d104server # [423680.214324] server systemd-resolved[119]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16105server # [423680.214359] 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 test106server # [423680.236453] server systemd-resolved[119]: Using system hostname 'server'.107server # [423680.237811] server systemd[1]: Started Network Name Resolution.108server # [423680.237889] server systemd[1]: Reached target Network.109server # [423680.237960] server systemd[1]: Reached target System Initialization.110server # [423680.238044] server systemd[1]: Started Watch for zone file changes.111server # [423680.238087] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container112server # [423680.238112] server systemd[1]: Started Daily Cleanup of Temporary Directories.113server # [423680.238135] server systemd[1]: Reached target Path Units.114server # [423680.238162] server systemd[1]: Reached target Timer Units.115server # [423680.238279] server systemd[1]: Listening on D-Bus System Message Bus Socket.116server # [423680.238399] server systemd[1]: Listening on Nix Daemon Socket.117server # [423680.238509] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.118server # [423680.238533] server systemd[1]: Reached target Socket Units.119server # [423680.238569] server systemd[1]: Reached target Basic System.120server # [423680.239815] server systemd[1]: Starting data mesher daemon...121server # [423680.240659] server systemd[1]: Starting Import lastlog data into lastlog2 database...122server # [423680.241572] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...123server # [423680.242871] server systemd[1]: Starting D-Bus System Message Bus...124server # [423680.310855] server systemd[1]: Finished Import lastlog data into lastlog2 database.125server # [423680.408463] server nsncd[220]: Sep 09 05:08:20.394 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"126server # [423680.408455] server systemd[1]: Started Name Service Cache Daemon (nsncd).127server # [423680.408541] server systemd[1]: Reached target User and Group Name Lookups.128server # [423680.409993] server systemd[1]: Starting User Login Management...129server # [423680.411032] server systemd[1]: Starting Permit User Sessions...130server # [423680.456568] server systemd[1]: Finished Permit User Sessions.131server # [423680.458354] server systemd[1]: Started Console Getty.132server # [423680.458435] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0133server # [423680.458477] server systemd[1]: Reached target Login Prompts.134server # [423680.485883] server systemd[1]: Finished Save Transient machine-id to Disk.135server # [423680.507035] server dbus-broker-launch[221]: Looking up NSS user entry for 'systemd-timesync'...136server # [423680.508204] server dbus-broker-launch[221]: NSS returned no entry for 'systemd-timesync'137server # [423680.508204] server dbus-broker-launch[221]: Invalid user-name in /nix/store/1d53z66ay3hkphfwrrbxmbrdhxr16y51-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"138server # [423680.508815] server systemd[1]: Started D-Bus System Message Bus.139server # [423680.516729] server dbus-broker-launch[221]: Ready140client # [423679.682136] client systemd[1]: Finished Update is Completed.141client # [423679.727516] client systemd[1]: Finished Firewall.142client # [423679.727716] client systemd[1]: Reached target Preparation for Network.143client # [423679.728026] client systemd[1]: Listening on Network Management Resolve Hook Socket.144client # [423679.729289] client systemd[1]: Starting Network Management...145client # [423680.140976] client systemd-networkd[203]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted146client # [423680.141072] client systemd-networkd[203]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted147client # [423680.147523] 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.148client # [423680.147691] 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.149client # [423680.147882] client systemd-networkd[203]: lo: Link UP150client # [423680.147889] client systemd-networkd[203]: lo: Gained carrier151client # [423680.148058] client systemd-networkd[203]: eth1: Configuring with /etc/systemd/network/40-eth1.network.152client # [423680.148493] client systemd[1]: Started Network Management.153client # [423680.148545] client systemd-networkd[203]: eth1: Link UP154client # [423680.148988] client systemd-networkd[203]: eth1: Gained carrier155client # [423680.150157] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd...156client # [423680.193909] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd.157client # [423680.219948] client systemd-resolved[108]: Positive Trust Anchors:158client # [423680.219961] client systemd-resolved[108]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d159client # [423680.219964] client systemd-resolved[108]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16160client # [423680.219999] client systemd-resolved[108]: 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 test161client # [423680.242515] client systemd-resolved[108]: Using system hostname 'client'.162client # [423680.243859] client systemd[1]: Started Network Name Resolution.163client # [423680.243939] client systemd[1]: Reached target Network.164client # [423680.244021] client systemd[1]: Reached target System Initialization.165client # [423680.244112] client systemd[1]: Started Watch for zone file changes.166client # [423680.244139] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container167client # [423680.244161] client systemd[1]: Started Daily Cleanup of Temporary Directories.168client # [423680.244182] client systemd[1]: Reached target Path Units.169client # [423680.244212] client systemd[1]: Reached target Timer Units.170client # [423680.244343] client systemd[1]: Listening on D-Bus System Message Bus Socket.171client # [423680.244447] client systemd[1]: Listening on Nix Daemon Socket.172client # [423680.244553] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.173client # [423680.244575] client systemd[1]: Reached target Socket Units.174client # [423680.244607] client systemd[1]: Reached target Basic System.175client # [423680.292762] client systemd[1]: Starting data mesher daemon...176client # [423680.293592] client systemd[1]: Starting Import lastlog data into lastlog2 database...177client # [423680.294465] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...178client # [423680.295674] client systemd[1]: Starting D-Bus System Message Bus...179client # [423680.315411] client systemd[1]: Finished Import lastlog data into lastlog2 database.180client # [423680.400636] client nsncd[210]: Sep 09 05:08:20.386 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"181client # [423680.400575] client systemd[1]: Started Name Service Cache Daemon (nsncd).182client # [423680.400663] client systemd[1]: Reached target User and Group Name Lookups.183client # [423680.405160] client systemd[1]: Starting User Login Management...184client # [423680.406620] client systemd[1]: Starting Permit User Sessions...185client # [423680.458516] client systemd[1]: Finished Permit User Sessions.186client # [423680.459863] client systemd[1]: Started Console Getty.187client # [423680.459917] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0188client # [423680.459957] client systemd[1]: Reached target Login Prompts.189client # [423680.484470] client systemd[1]: Finished Save Transient machine-id to Disk.190client # [423680.489275] client dbus-broker-launch[211]: Looking up NSS user entry for 'systemd-timesync'...191client # [423680.490825] client dbus-broker-launch[211]: NSS returned no entry for 'systemd-timesync'192client # [423680.490825] client dbus-broker-launch[211]: Invalid user-name in /nix/store/vv772f45jg5884k1j3pd5hpkwfd9f6x4-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"193client # [423680.491257] client systemd[1]: Started D-Bus System Message Bus.194client # [423680.499860] client dbus-broker-launch[211]: Ready195client # [423680.551892] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.196server # [423680.550618] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.197client # [423680.726562] client data-mesher[208]: time=2026-09-09T05:08:20.712Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]198client # [423680.727650] client data-mesher[208]: time=2026-09-09T05:08:20.713Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWGgkBnk4yA7NW52QmYDnL37LHKrwQnWEcqptduGGEedZi: [/dns/client.test/tcp/7946]} {12D3KooWNjUSMr13mCK2PA5MSkqFHKghCCZgVMYaPJ1SLFAM95SK: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWGgkBnk4yA7NW52QmYDnL37LHKrwQnWEcqptduGGEedZi199client # [423680.727699] client data-mesher[208]: time=2026-09-09T05:08:20.713Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml200client # [423680.740372] client data-mesher[208]: time=2026-09-09T05:08:20.726Z level=INFO msg="checking file integrity"201client # [423680.740492] client data-mesher[208]: time=2026-09-09T05:08:20.726Z level=INFO msg="file integrity check complete"202client # [423680.744506] client data-mesher[208]: time=2026-09-09T05:08:20.730Z level=INFO msg="libp2p host created" peer_id=12D3KooWGgkBnk4yA7NW52QmYDnL37LHKrwQnWEcqptduGGEedZi 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]"203client # [423680.744549] client data-mesher[208]: time=2026-09-09T05:08:20.730Z level=INFO msg="registered HTTP route" method=GET path=/files204client # [423680.744549] client data-mesher[208]: time=2026-09-09T05:08:20.730Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name205client # [423680.744549] client data-mesher[208]: time=2026-09-09T05:08:20.730Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name206client # [423680.744549] client data-mesher[208]: time=2026-09-09T05:08:20.730Z level=INFO msg="starting server"207client # [423680.744639] client data-mesher[208]: time=2026-09-09T05:08:20.730Z level=INFO msg="waiting for DHT to populate" delay=10s208client # [423680.744769] client data-mesher[208]: time=2026-09-09T05:08:20.730Z level=INFO msg="HTTP server listening" address=[::1]:7331209client # [423680.744803] client data-mesher[208]: time=2026-09-09T05:08:20.730Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331210client # [423680.754815] client data-mesher[208]: time=2026-09-09T05:08:20.740Z level=INFO msg="peer connected" peer_id=12D3KooWNjUSMr13mCK2PA5MSkqFHKghCCZgVMYaPJ1SLFAM95SK remote_addr=/ip4/192.168.1.2/tcp/7946211client # [423680.778342] client data-mesher[208]: time=2026-09-09T05:08:20.764Z level=INFO msg="peer connected" peer_id=12D3KooWNjUSMr13mCK2PA5MSkqFHKghCCZgVMYaPJ1SLFAM95SK remote_addr=/ip4/192.168.1.2/tcp/7946212client # [423680.880322] client systemd-logind[228]: New seat seat0.213client # [423680.880530] client systemd[1]: Started User Login Management.214client # [423680.882790] client systemd[1]: Starting linger-users.service...215client # [423680.932096] client systemd[1]: linger-users.service: Deactivated successfully.216client # [423680.932289] client systemd[1]: Finished linger-users.service.217server # [423680.741485] server data-mesher[218]: time=2026-09-09T05:08:20.727Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]218server # [423680.742579] server data-mesher[218]: time=2026-09-09T05:08:20.728Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWGgkBnk4yA7NW52QmYDnL37LHKrwQnWEcqptduGGEedZi: [/dns/client.test/tcp/7946]} {12D3KooWNjUSMr13mCK2PA5MSkqFHKghCCZgVMYaPJ1SLFAM95SK: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWNjUSMr13mCK2PA5MSkqFHKghCCZgVMYaPJ1SLFAM95SK219server # [423680.742579] server data-mesher[218]: time=2026-09-09T05:08:20.728Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml220server # [423680.744106] server data-mesher[218]: time=2026-09-09T05:08:20.729Z level=INFO msg="checking file integrity"221server # [423680.744227] server data-mesher[218]: time=2026-09-09T05:08:20.730Z level=INFO msg="file integrity check complete"222server # [423680.747971] server data-mesher[218]: time=2026-09-09T05:08:20.733Z level=INFO msg="libp2p host created" peer_id=12D3KooWNjUSMr13mCK2PA5MSkqFHKghCCZgVMYaPJ1SLFAM95SK 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]"223server # [423680.748059] server data-mesher[218]: time=2026-09-09T05:08:20.733Z level=INFO msg="registered HTTP route" method=GET path=/files224server # [423680.748059] server data-mesher[218]: time=2026-09-09T05:08:20.733Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name225server # [423680.748059] server data-mesher[218]: time=2026-09-09T05:08:20.733Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name226server # [423680.748059] server data-mesher[218]: time=2026-09-09T05:08:20.733Z level=INFO msg="starting server"227server # [423680.748172] server data-mesher[218]: time=2026-09-09T05:08:20.733Z level=INFO msg="waiting for DHT to populate" delay=10s228server # [423680.748297] server data-mesher[218]: time=2026-09-09T05:08:20.734Z level=INFO msg="HTTP server listening" address=[::1]:7331229server # [423680.748339] server data-mesher[218]: time=2026-09-09T05:08:20.734Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331230server # [423680.753855] server data-mesher[218]: time=2026-09-09T05:08:20.739Z level=INFO msg="peer connected" peer_id=12D3KooWGgkBnk4yA7NW52QmYDnL37LHKrwQnWEcqptduGGEedZi remote_addr=/ip4/192.168.1.1/tcp/7946231server # [423680.779024] server data-mesher[218]: time=2026-09-09T05:08:20.764Z level=INFO msg="peer connected" peer_id=12D3KooWGgkBnk4yA7NW52QmYDnL37LHKrwQnWEcqptduGGEedZi remote_addr=/ip4/192.168.1.1/tcp/55356232server # [423680.892948] server systemd-logind[238]: New seat seat0.233server # [423680.893174] server systemd[1]: Started User Login Management.234server # [423680.924480] server systemd[1]: Starting linger-users.service...235server # [423680.937711] server systemd[1]: linger-users.service: Deactivated successfully.236server # [423680.937838] server systemd[1]: Finished linger-users.service.237server # [423681.536283] server systemd-networkd[213]: eth1: Gained IPv6LL238client # [423681.760198] client systemd-networkd[203]: eth1: Gained IPv6LL239server: still waiting for container 'server' to reach ready state...240client # [423690.745219] client data-mesher[208]: time=2026-09-09T05:08:30.731Z level=INFO msg="performing state exchange with peers on join" count=1241client # [423690.745219] client data-mesher[208]: time=2026-09-09T05:08:30.731Z level=DEBUG msg="initiating state exchange" peer=12D3KooWNjUSMr13mCK2PA5MSkqFHKghCCZgVMYaPJ1SLFAM95SK timeout=5s242client # [423690.746012] client data-mesher[208]: time=2026-09-09T05:08:30.731Z level=INFO msg="merging remote state" peer=12D3KooWNjUSMr13mCK2PA5MSkqFHKghCCZgVMYaPJ1SLFAM95SK243client # [423690.746012] client data-mesher[208]: time=2026-09-09T05:08:30.731Z level=INFO msg="state exchange complete" peer=12D3KooWNjUSMr13mCK2PA5MSkqFHKghCCZgVMYaPJ1SLFAM95SK timeout=5s244client # [423690.746086] client data-mesher[208]: time=2026-09-09T05:08:30.731Z level=INFO msg="server started"245client # [423690.746230] client data-mesher[208]: time=2026-09-09T05:08:30.732Z level=INFO msg="starting expired-file sweeper" interval=1m0s246client # [423690.746255] client systemd[1]: Started data mesher daemon.247client # [423690.747738] client systemd[1]: Starting Unbound recursive Domain Name Server...248client # [423690.748970] client data-mesher[208]: time=2026-09-09T05:08:30.734Z level=INFO msg="received state sync from peer" peer=12D3KooWNjUSMr13mCK2PA5MSkqFHKghCCZgVMYaPJ1SLFAM95SK249client # [423690.749014] client data-mesher[208]: time=2026-09-09T05:08:30.734Z level=INFO msg="merging remote state" peer=12D3KooWNjUSMr13mCK2PA5MSkqFHKghCCZgVMYaPJ1SLFAM95SK250server # [423690.745873] server data-mesher[218]: time=2026-09-09T05:08:30.731Z level=INFO msg="received state sync from peer" peer=12D3KooWGgkBnk4yA7NW52QmYDnL37LHKrwQnWEcqptduGGEedZi251server # [423690.745873] server data-mesher[218]: time=2026-09-09T05:08:30.731Z level=INFO msg="merging remote state" peer=12D3KooWGgkBnk4yA7NW52QmYDnL37LHKrwQnWEcqptduGGEedZi252server # [423690.748517] server data-mesher[218]: time=2026-09-09T05:08:30.734Z level=INFO msg="performing state exchange with peers on join" count=1253server # [423690.748619] server data-mesher[218]: time=2026-09-09T05:08:30.734Z level=DEBUG msg="initiating state exchange" peer=12D3KooWGgkBnk4yA7NW52QmYDnL37LHKrwQnWEcqptduGGEedZi timeout=5s254server # [423690.749203] server data-mesher[218]: time=2026-09-09T05:08:30.735Z level=INFO msg="merging remote state" peer=12D3KooWGgkBnk4yA7NW52QmYDnL37LHKrwQnWEcqptduGGEedZi255server # [423690.749203] server data-mesher[218]: time=2026-09-09T05:08:30.735Z level=INFO msg="state exchange complete" peer=12D3KooWGgkBnk4yA7NW52QmYDnL37LHKrwQnWEcqptduGGEedZi timeout=5s256server # [423690.749360] server data-mesher[218]: time=2026-09-09T05:08:30.735Z level=INFO msg="server started"257server # [423690.749360] server data-mesher[218]: time=2026-09-09T05:08:30.735Z level=INFO msg="starting expired-file sweeper" interval=1m0s258server # [423690.749495] server systemd[1]: Started data mesher daemon.259server # [423690.751045] server systemd[1]: Starting Unbound recursive Domain Name Server...260server # [423691.270064] server unbound-pre-start[281]: Root anchor updated!261server # [423691.288202] server unbound-pre-start[285]: setup in directory /var/lib/unbound262client # [423691.267516] client unbound-pre-start[271]: Root anchor updated!263client # [423691.281280] client unbound-pre-start[275]: setup in directory /var/lib/unbound264client # [423693.280535] client unbound-pre-start[284]: Certificate request self-signature ok265client # [423693.280535] client unbound-pre-start[284]: subject=CN=unbound-control266client # [423693.299785] client unbound-pre-start[275]: removing artifacts267client # [423693.301592] client unbound-pre-start[275]: Setup success. Certificates created. Enable in unbound.conf file to use268server # [423693.375483] server unbound-pre-start[294]: Certificate request self-signature ok269server # [423693.375483] server unbound-pre-start[294]: subject=CN=unbound-control270server # [423693.395662] server unbound-pre-start[285]: removing artifacts271server # [423693.397789] server unbound-pre-start[285]: Setup success. Certificates created. Enable in unbound.conf file to use272client # [423693.823037] client unbound[289]: [289:0] notice: init module 0: validator273client # [423693.823147] client unbound[289]: [289:0] notice: init module 1: iterator274client # [423693.829458] client unbound[289]: [289:0] info: start of service (unbound 1.26.0).275client # [423693.829548] client systemd[1]: Started Unbound recursive Domain Name Server.276client # [423693.829769] client systemd[1]: Reached target Multi-User System.277client # [423693.829885] client systemd[1]: Reached target Host and Network Name Lookups.278client # [423693.830934] client systemd[1]: Starting Reload unbound zone configuration...279client # [423693.881875] client unbound[289]: [289:0] info: service stopped (unbound 1.26.0).280client # [423693.882228] client unbound-control[292]: ok281client # [423693.882223] 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 ratelimiting282client # [423693.882228] client unbound[289]: [289:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0283client # [423693.883848] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.284client # [423693.883982] client unbound[289]: [289:0] notice: Restart of unbound 1.26.0.285client # [423693.884249] client systemd[1]: Finished Reload unbound zone configuration.286client # [423693.884813] client systemd[1]: Startup finished in 14.808s.287client # [423693.884885] client unbound[289]: [289:0] notice: init module 0: validator288client # [423693.884942] client unbound[289]: [289:0] notice: init module 1: iterator289client # [423693.889576] client unbound[289]: [289:0] info: start of service (unbound 1.26.0).290server # [423693.892875] server unbound[299]: [299:0] notice: init module 0: validator291server # [423693.892990] server unbound[299]: [299:0] notice: init module 1: iterator292server # [423693.898756] server unbound[299]: [299:0] info: start of service (unbound 1.26.0).293server # [423693.898914] server systemd[1]: Started Unbound recursive Domain Name Server.294server # [423693.899403] server systemd[1]: Reached target Multi-User System.295server # [423693.899679] server systemd[1]: Reached target Host and Network Name Lookups.296server # [423693.901510] server systemd[1]: Starting Reload unbound zone configuration...297server # [423693.945983] server unbound[299]: [299:0] info: service stopped (unbound 1.26.0).298server # [423693.946348] server unbound-control[302]: ok299server # [423693.946346] server unbound[299]: [299:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting300server # [423693.946351] server unbound[299]: [299:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0301server # [423693.947757] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.302server # [423693.948061] server systemd[1]: Finished Reload unbound zone configuration.303server # [423693.948138] server unbound[299]: [299:0] notice: Restart of unbound 1.26.0.304server # [423693.948561] server systemd[1]: Startup finished in 14.845s.305server # [423693.949066] server unbound[299]: [299:0] notice: init module 0: validator306server # [423693.949135] server unbound[299]: [299:0] notice: init module 1: iterator307server # [423693.953756] server unbound[299]: [299:0] info: start of service (unbound 1.26.0).308server: (finished: waiting for unit unbound.service, in 15.68 seconds)309client: waiting for unit unbound.service310client: (finished: waiting for unit unbound.service, in 0.02 seconds)311server: waiting for unit data-mesher.service312server: (finished: waiting for unit data-mesher.service, in 0.02 seconds)313server: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1314server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1, in 0.02 seconds)315server: must succeed: data-mesher file update --network-id /nix/store/nf33b4sdl2w46mw2pnlyyj2cmpd4aimy-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/cnames316server: (finished: must succeed: data-mesher file update --network-id /nix/store/nf33b4sdl2w46mw2pnlyyj2cmpd4aimy-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)317??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.318 File "/nix/store/jgv4ks38rw752dikiay8dry62yxa7ybk-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39319server: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test320??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.321 File "/nix/store/jgv4ks38rw752dikiay8dry62yxa7ybk-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39322server # [423694.299996] server systemd[1]: Starting Reload unbound zone configuration...323server # [423694.308613] server data-mesher[218]: time=2026-09-09T05:08:34.294Z level=INFO msg=http_request uri=/files/dns/cnames status=204324server # [423694.350457] server unbound[299]: [299:0] info: service stopped (unbound 1.26.0).325server # [423694.350614] server unbound-control[336]: ok326server # [423694.351069] server unbound[299]: [299:0] info: server stats for thread 0: 5 queries, 2 answers from cache, 3 recursions, 0 prefetch, 0 rejected by ip ratelimiting327server # [423694.351080] server unbound[299]: [299:0] info: server stats for thread 0: requestlist max 2 avg 1.33333 exceeded 0 jostled 0328server # [423694.352122] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.329server # [423694.352439] server systemd[1]: Finished Reload unbound zone configuration.330server # [423694.353207] server unbound[299]: [299:0] notice: Restart of unbound 1.26.0.331server # [423694.355044] server unbound[299]: [299:0] notice: init module 0: validator332server # [423694.355154] server unbound[299]: [299:0] notice: init module 1: iterator333server # [423694.365371] server unbound[299]: [299:0] info: start of service (unbound 1.26.0).334server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test, in 1.05 seconds)335(finished: run the VM test script, in 16.84 seconds)336test script finished in 16.87s337cleanup338kill NspawnMachine (pid 52)339kill NspawnMachine (pid 53)340Container client terminated by signal KILL.341Container server terminated by signal KILL.342(finished: cleanup, in 0.38 seconds)