container-test-run-dm-dns
checks.aarch64-linux.dm-dns
· build #500
· raw
1Machine state will be reset. To keep it, pass --keep-machine-state2start all VLans3(finished: start all VLans, in 0.01 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.27client # No journal boot entry found for the specified boot (+0).28server # No journal files were found.29server # No journal boot entry found for the specified boot (+0).30client # [6727699.053929] client systemd-journald[87]: Journal started31client # [6727699.053993] client systemd-journald[87]: Runtime Journal (/run/log/journal/4c9e825430284012ad3d366497aae566) is 8M, max 2.5G, 2.4G free.32client # [6727699.057815] client systemd[1]: Finished Apply Kernel Variables.33client # [6727699.065025] client systemd[1]: Finished Create Static Device Nodes in /dev gracefully.34client # [6727699.075177] client systemd[1]: Starting Flush Journal to Persistent Storage...35client # [6727699.076359] client systemd[1]: Starting Network Name Resolution...36client # [6727699.077227] client systemd[1]: Starting Create Static Device Nodes in /dev...37client # [6727699.086415] client systemd-journald[87]: Time spent on flushing to /var/log/journal/4c9e825430284012ad3d366497aae566 is 1.860ms for 7 entries.38client # [6727699.086415] client systemd-journald[87]: System Journal (/var/log/journal/4c9e825430284012ad3d366497aae566) is 8M, max 4G, 3.9G free.39client # [6727699.093597] client systemd[1]: Finished Create Static Device Nodes in /dev.40client # [6727699.094450] client systemd[1]: Reached target Preparation for Local File Systems.41client # [6727699.094576] client systemd[1]: Reached target Local File Systems.42client # [6727699.095536] client systemd[1]: Listening on Boot Loader Control Service Socket.43client # [6727699.095587] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container44client # [6727699.098671] client systemd[1]: Starting Save Transient machine-id to Disk...45client # [6727699.098732] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys46client # [6727699.107048] client systemd[1]: Finished Flush Journal to Persistent Storage.47client # [6727699.108874] client systemd[1]: Starting Create System Files and Directories...48client # [6727699.124847] client systemd-tmpfiles[139]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted49client # [6727699.125048] client systemd-tmpfiles[139]: fchmod() of /var/log/journal failed: Operation not permitted50client # [6727699.125186] client systemd-tmpfiles[139]: fchmod() of /var/log/journal/4c9e825430284012ad3d366497aae566 failed: Operation not permitted51client # [6727699.125404] client systemd-tmpfiles[139]: fchmod() of /run/log/journal failed: Operation not permitted52client # [6727699.192957] client systemd[1]: Finished Create System Files and Directories.53client # [6727699.194403] client systemd[1]: Starting Rebuild Journal Catalog...54client # [6727699.195550] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...55client # [6727699.207994] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.56client # [6727699.216504] client systemd[1]: Finished Rebuild Journal Catalog.57client # [6727699.218008] client systemd[1]: Starting Update is Completed...58client # [6727699.226611] client systemd[1]: Finished Firewall.59client # [6727699.226797] client systemd[1]: Reached target Preparation for Network.60client # [6727699.227106] client systemd[1]: Listening on Network Management Resolve Hook Socket.61client # [6727699.228290] client systemd[1]: Starting Network Management...62client # [6727699.230977] client systemd[1]: Finished Update is Completed.63client # [6727699.532445] client systemd[1]: Finished Save Transient machine-id to Disk.64client # [6727699.851931] client systemd-networkd[203]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted65client # [6727699.852056] client systemd-networkd[203]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted66client # [6727699.859179] 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.67client # [6727699.859350] 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.68client # [6727699.859587] client systemd-networkd[203]: lo: Link UP69client # [6727699.859594] client systemd-networkd[203]: lo: Gained carrier70client # [6727699.859840] client systemd-networkd[203]: eth1: Configuring with /etc/systemd/network/40-eth1.network.71client # [6727699.860405] client systemd[1]: Started Network Management.72client # [6727699.860702] client systemd-networkd[203]: eth1: Link UP73client # [6727699.860937] client systemd-networkd[203]: eth1: Gained carrier74client # [6727699.861773] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd...75client # [6727699.986581] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd.76server # [6727699.050430] server systemd-journald[96]: Journal started77server # [6727699.050494] server systemd-journald[96]: Runtime Journal (/run/log/journal/7bc83a3f2783487ead8bb7034830b304) is 8M, max 2.5G, 2.4G free.78server # [6727699.055446] server systemd[1]: Finished Create Static Device Nodes in /dev gracefully.79server # [6727699.065534] server systemd[1]: Starting Flush Journal to Persistent Storage...80server # [6727699.067123] server systemd[1]: Starting Network Name Resolution...81server # [6727699.068083] server systemd[1]: Starting Create Static Device Nodes in /dev...82server # [6727699.077049] server systemd-journald[96]: Time spent on flushing to /var/log/journal/7bc83a3f2783487ead8bb7034830b304 is 1.800ms for 6 entries.83server # [6727699.077049] server systemd-journald[96]: System Journal (/var/log/journal/7bc83a3f2783487ead8bb7034830b304) is 8M, max 4G, 3.9G free.84server # [6727699.084735] server systemd[1]: Finished Create Static Device Nodes in /dev.85server # [6727699.085076] server systemd[1]: Reached target Preparation for Local File Systems.86server # [6727699.085259] server systemd[1]: Reached target Local File Systems.87server # [6727699.086121] server systemd[1]: Listening on Boot Loader Control Service Socket.88server # [6727699.086173] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container89server # [6727699.087253] server systemd[1]: Starting Save Transient machine-id to Disk...90server # [6727699.087303] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys91server # [6727699.096496] server systemd[1]: Finished Flush Journal to Persistent Storage.92server # [6727699.097746] server systemd[1]: Starting Create System Files and Directories...93server # [6727699.115766] server systemd-tmpfiles[143]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted94server # [6727699.115992] server systemd-tmpfiles[143]: fchmod() of /var/log/journal failed: Operation not permitted95server # [6727699.116164] server systemd-tmpfiles[143]: fchmod() of /var/log/journal/7bc83a3f2783487ead8bb7034830b304 failed: Operation not permitted96server # [6727699.116402] server systemd-tmpfiles[143]: fchmod() of /run/log/journal failed: Operation not permitted97server # [6727699.192964] server systemd[1]: Finished Create System Files and Directories.98server # [6727699.194389] server systemd[1]: Starting Rebuild Journal Catalog...99server # [6727699.195605] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...100server # [6727699.208041] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.101server # [6727699.215773] server systemd[1]: Finished Rebuild Journal Catalog.102server # [6727699.217349] server systemd[1]: Starting Update is Completed...103server # [6727699.222821] server systemd[1]: Finished Firewall.104server # [6727699.222991] server systemd[1]: Reached target Preparation for Network.105server # [6727699.223243] server systemd[1]: Listening on Network Management Resolve Hook Socket.106server # [6727699.224553] server systemd[1]: Starting Network Management...107server # [6727699.230942] server systemd[1]: Finished Update is Completed.108server # [6727699.536505] server systemd[1]: Finished Save Transient machine-id to Disk.109server # [6727699.827836] server systemd-networkd[212]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted110server # [6727699.827937] server systemd-networkd[212]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted111server # [6727699.836174] server systemd-networkd[212]: /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.112server # [6727699.836349] server systemd-networkd[212]: /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.113server # [6727699.836565] server systemd-networkd[212]: lo: Link UP114server # [6727699.836569] server systemd-networkd[212]: lo: Gained carrier115server # [6727699.837218] server systemd-networkd[212]: eth1: Configuring with /etc/systemd/network/40-eth1.network.116server # [6727699.837769] server systemd[1]: Started Network Management.117server # [6727699.837816] server systemd-networkd[212]: eth1: Link UP118server # [6727699.838055] server systemd-networkd[212]: eth1: Gained carrier119server # [6727699.839013] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...120server # [6727699.975405] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.121client # [6727700.040841] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.122server # [6727700.038415] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.123server # [6727700.117120] server systemd-resolved[121]: Positive Trust Anchors:124server # [6727700.117136] server systemd-resolved[121]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d125server # [6727700.117139] server systemd-resolved[121]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16126server # [6727700.117173] server systemd-resolved[121]: 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 test127server # [6727700.142552] server systemd-resolved[121]: Using system hostname 'server'.128server # [6727700.144240] server systemd[1]: Started Network Name Resolution.129server # [6727700.144345] server systemd[1]: Reached target Network.130server # [6727700.144427] server systemd[1]: Reached target System Initialization.131server # [6727700.144523] server systemd[1]: Started Watch for zone file changes.132server # [6727700.144632] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container133server # [6727700.144665] server systemd[1]: Started Daily Cleanup of Temporary Directories.134server # [6727700.144687] server systemd[1]: Reached target Path Units.135server # [6727700.144722] server systemd[1]: Reached target Timer Units.136server # [6727700.144858] server systemd[1]: Listening on D-Bus System Message Bus Socket.137server # [6727700.144986] server systemd[1]: Listening on Nix Daemon Socket.138server # [6727700.145098] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.139server # [6727700.145121] server systemd[1]: Reached target Socket Units.140server # [6727700.145157] server systemd[1]: Reached target Basic System.141server # [6727700.147001] server systemd[1]: Starting data mesher daemon...142server # [6727700.147980] server systemd[1]: Starting Import lastlog data into lastlog2 database...143server # [6727700.149194] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...144server # [6727700.150675] server systemd[1]: Starting D-Bus System Message Bus...145server # [6727700.270187] server systemd[1]: Finished Import lastlog data into lastlog2 database.146server # [6727700.362556] server nsncd[221]: Aug 25 20:12:06.415 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"147server # [6727700.362701] server systemd[1]: Started Name Service Cache Daemon (nsncd).148server # [6727700.362787] server systemd[1]: Reached target User and Group Name Lookups.149server # [6727700.364384] server systemd[1]: Starting User Login Management...150server # [6727700.365415] server systemd[1]: Starting Permit User Sessions...151client # [6727700.146929] client systemd-resolved[116]: Positive Trust Anchors:152client # [6727700.146944] client systemd-resolved[116]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d153client # [6727700.146947] client systemd-resolved[116]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16154client # [6727700.146983] client systemd-resolved[116]: 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 test155client # [6727700.172489] client systemd-resolved[116]: Using system hostname 'client'.156client # [6727700.174148] client systemd[1]: Started Network Name Resolution.157client # [6727700.174250] client systemd[1]: Reached target Network.158client # [6727700.174320] client systemd[1]: Reached target System Initialization.159client # [6727700.174410] client systemd[1]: Started Watch for zone file changes.160client # [6727700.174442] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container161client # [6727700.174466] client systemd[1]: Started Daily Cleanup of Temporary Directories.162client # [6727700.174485] client systemd[1]: Reached target Path Units.163client # [6727700.174523] client systemd[1]: Reached target Timer Units.164client # [6727700.174654] client systemd[1]: Listening on D-Bus System Message Bus Socket.165client # [6727700.174779] client systemd[1]: Listening on Nix Daemon Socket.166client # [6727700.174894] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.167client # [6727700.174921] client systemd[1]: Reached target Socket Units.168client # [6727700.174963] client systemd[1]: Reached target Basic System.169client # [6727700.253820] client systemd[1]: Starting data mesher daemon...170client # [6727700.255025] client systemd[1]: Starting Import lastlog data into lastlog2 database...171client # [6727700.256134] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...172client # [6727700.257620] client systemd[1]: Starting D-Bus System Message Bus...173client # [6727700.275208] client systemd[1]: Finished Import lastlog data into lastlog2 database.174client # [6727700.364582] client nsncd[212]: Aug 25 20:12:06.417 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"175client # [6727700.364717] client systemd[1]: Started Name Service Cache Daemon (nsncd).176client # [6727700.364787] client systemd[1]: Reached target User and Group Name Lookups.177client # [6727700.366153] client systemd[1]: Starting User Login Management...178client # [6727700.366978] client systemd[1]: Starting Permit User Sessions...179client # [6727700.419549] client systemd[1]: Finished Permit User Sessions.180client # [6727700.420794] client systemd[1]: Started Console Getty.181client # [6727700.420844] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0182client # [6727700.420864] client systemd[1]: Reached target Login Prompts.183client # [6727700.570797] client dbus-broker-launch[213]: Looking up NSS user entry for 'systemd-timesync'...184client # [6727700.572662] client dbus-broker-launch[213]: NSS returned no entry for 'systemd-timesync'185client # [6727700.572662] client dbus-broker-launch[213]: Invalid user-name in /nix/store/s1gm54qxyci4kv7f3yrzv6kxm0jf1vmp-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"186client # [6727700.573264] client systemd[1]: Started D-Bus System Message Bus.187client # [6727700.581038] client dbus-broker-launch[213]: Ready188server # [6727700.422065] server systemd[1]: Finished Permit User Sessions.189server # [6727700.423302] server systemd[1]: Started Console Getty.190server # [6727700.423365] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0191server # [6727700.423393] server systemd[1]: Reached target Login Prompts.192server # [6727700.582293] server dbus-broker-launch[222]: Looking up NSS user entry for 'systemd-timesync'...193server # [6727700.583294] server dbus-broker-launch[222]: NSS returned no entry for 'systemd-timesync'194server # [6727700.583294] server dbus-broker-launch[222]: Invalid user-name in /nix/store/wyyrnm3f3s5jzhkfrz52nbd2i1lr51wd-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"195server # [6727700.583714] server systemd[1]: Started D-Bus System Message Bus.196server # [6727700.591048] server dbus-broker-launch[222]: Ready197server # [6727701.060570] server systemd-networkd[212]: eth1: Gained IPv6LL198client # [6727701.284435] client systemd-networkd[203]: eth1: Gained IPv6LL199client # [6727703.460572] client data-mesher[210]: time=2026-08-25T20:12:09.513Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]200client # [6727703.461754] client data-mesher[210]: time=2026-08-25T20:12:09.514Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWBj7uboyJQJPwNvkdgLdF2U7c3VVj1EnASBg7ws49ki6L: [/dns/client.test/tcp/7946]} {12D3KooWHPoP8vedGqWDJukeAXLQpcpVW93VyPrUMJ49bXEpWAr3: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWBj7uboyJQJPwNvkdgLdF2U7c3VVj1EnASBg7ws49ki6L201client # [6727703.461754] client data-mesher[210]: time=2026-08-25T20:12:09.514Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml202client # [6727703.546765] client data-mesher[210]: time=2026-08-25T20:12:09.599Z level=INFO msg="checking file integrity"203client # [6727703.546995] client data-mesher[210]: time=2026-08-25T20:12:09.600Z level=INFO msg="file integrity check complete"204client # [6727703.556072] client data-mesher[210]: time=2026-08-25T20:12:09.605Z level=INFO msg="libp2p host created" peer_id=12D3KooWBj7uboyJQJPwNvkdgLdF2U7c3VVj1EnASBg7ws49ki6L 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 # [6727703.556072] client data-mesher[210]: time=2026-08-25T20:12:09.605Z level=INFO msg="registered HTTP route" method=GET path=/files206client # [6727703.556072] client data-mesher[210]: time=2026-08-25T20:12:09.605Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name207client # [6727703.556072] client data-mesher[210]: time=2026-08-25T20:12:09.605Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name208client # [6727703.556072] client data-mesher[210]: time=2026-08-25T20:12:09.606Z level=INFO msg="starting server"209client # [6727703.556072] client data-mesher[210]: time=2026-08-25T20:12:09.606Z level=INFO msg="waiting for DHT to populate" delay=10s210client # [6727703.556072] client data-mesher[210]: time=2026-08-25T20:12:09.606Z level=INFO msg="HTTP server listening" address=[::1]:7331211client # [6727703.556072] client data-mesher[210]: time=2026-08-25T20:12:09.606Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331212client # [6727703.672070] client data-mesher[210]: time=2026-08-25T20:12:09.722Z level=INFO msg="peer connected" peer_id=12D3KooWHPoP8vedGqWDJukeAXLQpcpVW93VyPrUMJ49bXEpWAr3 remote_addr=/ip4/192.168.1.2/tcp/7946213server # [6727703.627440] server data-mesher[219]: time=2026-08-25T20:12:09.676Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]214server # [6727703.627440] server data-mesher[219]: time=2026-08-25T20:12:09.678Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWBj7uboyJQJPwNvkdgLdF2U7c3VVj1EnASBg7ws49ki6L: [/dns/client.test/tcp/7946]} {12D3KooWHPoP8vedGqWDJukeAXLQpcpVW93VyPrUMJ49bXEpWAr3: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWHPoP8vedGqWDJukeAXLQpcpVW93VyPrUMJ49bXEpWAr3215server # [6727703.627440] server data-mesher[219]: time=2026-08-25T20:12:09.678Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml216server # [6727703.643378] server data-mesher[219]: time=2026-08-25T20:12:09.693Z level=INFO msg="checking file integrity"217server # [6727703.644205] server data-mesher[219]: time=2026-08-25T20:12:09.697Z level=INFO msg="file integrity check complete"218server # [6727703.652989] server data-mesher[219]: time=2026-08-25T20:12:09.704Z level=INFO msg="libp2p host created" peer_id=12D3KooWHPoP8vedGqWDJukeAXLQpcpVW93VyPrUMJ49bXEpWAr3 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]"219server # [6727703.652989] server data-mesher[219]: time=2026-08-25T20:12:09.704Z level=INFO msg="registered HTTP route" method=GET path=/files220server # [6727703.652989] server data-mesher[219]: time=2026-08-25T20:12:09.704Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name221server # [6727703.652989] server data-mesher[219]: time=2026-08-25T20:12:09.704Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name222server # [6727703.652989] server data-mesher[219]: time=2026-08-25T20:12:09.704Z level=INFO msg="starting server"223server # [6727703.652989] server data-mesher[219]: time=2026-08-25T20:12:09.704Z level=INFO msg="waiting for DHT to populate" delay=10s224server # [6727703.652989] server data-mesher[219]: time=2026-08-25T20:12:09.704Z level=INFO msg="HTTP server listening" address=[::1]:7331225server # [6727703.652989] server data-mesher[219]: time=2026-08-25T20:12:09.704Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331226server # [6727703.672094] server data-mesher[219]: time=2026-08-25T20:12:09.721Z level=INFO msg="peer connected" peer_id=12D3KooWBj7uboyJQJPwNvkdgLdF2U7c3VVj1EnASBg7ws49ki6L remote_addr=/ip4/192.168.1.1/tcp/7946227client # [6727704.359208] client systemd-logind[230]: New seat seat0.228client # [6727704.359571] client systemd[1]: Started User Login Management.229client # [6727704.373821] client systemd[1]: Starting linger-users.service...230client # [6727704.483736] client systemd[1]: linger-users.service: Deactivated successfully.231client # [6727704.483894] client systemd[1]: Finished linger-users.service.232server # [6727704.409330] server systemd-logind[239]: New seat seat0.233server # [6727704.409582] server systemd[1]: Started User Login Management.234server # [6727704.425825] server systemd[1]: Starting linger-users.service...235server # [6727704.481848] server systemd[1]: linger-users.service: Deactivated successfully.236server # [6727704.482027] server systemd[1]: Finished linger-users.service.237server: still waiting for container 'server' to reach ready state...238server # [6727713.553871] server data-mesher[219]: time=2026-08-25T20:12:19.607Z level=INFO msg="received state sync from peer" peer=12D3KooWBj7uboyJQJPwNvkdgLdF2U7c3VVj1EnASBg7ws49ki6L239server # [6727713.553871] server data-mesher[219]: time=2026-08-25T20:12:19.607Z level=INFO msg="merging remote state" peer=12D3KooWBj7uboyJQJPwNvkdgLdF2U7c3VVj1EnASBg7ws49ki6L240server # [6727713.652212] server data-mesher[219]: time=2026-08-25T20:12:19.705Z level=INFO msg="performing state exchange with peers on join" count=1241server # [6727713.652212] server data-mesher[219]: time=2026-08-25T20:12:19.705Z level=DEBUG msg="initiating state exchange" peer=12D3KooWBj7uboyJQJPwNvkdgLdF2U7c3VVj1EnASBg7ws49ki6L timeout=5s242server # [6727713.652833] server data-mesher[219]: time=2026-08-25T20:12:19.705Z level=INFO msg="merging remote state" peer=12D3KooWBj7uboyJQJPwNvkdgLdF2U7c3VVj1EnASBg7ws49ki6L243server # [6727713.652833] server data-mesher[219]: time=2026-08-25T20:12:19.705Z level=INFO msg="state exchange complete" peer=12D3KooWBj7uboyJQJPwNvkdgLdF2U7c3VVj1EnASBg7ws49ki6L timeout=5s244server # [6727713.652833] server data-mesher[219]: time=2026-08-25T20:12:19.705Z level=INFO msg="server started"245server # [6727713.652967] server data-mesher[219]: time=2026-08-25T20:12:19.706Z level=INFO msg="starting expired-file sweeper" interval=1m0s246server # [6727713.652971] server systemd[1]: Started data mesher daemon.247server # [6727713.654505] server systemd[1]: Starting Unbound recursive Domain Name Server...248client # [6727713.553525] client data-mesher[210]: time=2026-08-25T20:12:19.606Z level=INFO msg="performing state exchange with peers on join" count=1249client # [6727713.553525] client data-mesher[210]: time=2026-08-25T20:12:19.606Z level=DEBUG msg="initiating state exchange" peer=12D3KooWHPoP8vedGqWDJukeAXLQpcpVW93VyPrUMJ49bXEpWAr3 timeout=5s250client # [6727713.554056] client data-mesher[210]: time=2026-08-25T20:12:19.607Z level=INFO msg="merging remote state" peer=12D3KooWHPoP8vedGqWDJukeAXLQpcpVW93VyPrUMJ49bXEpWAr3251client # [6727713.554056] client data-mesher[210]: time=2026-08-25T20:12:19.607Z level=INFO msg="state exchange complete" peer=12D3KooWHPoP8vedGqWDJukeAXLQpcpVW93VyPrUMJ49bXEpWAr3 timeout=5s252client # [6727713.554116] client data-mesher[210]: time=2026-08-25T20:12:19.607Z level=INFO msg="server started"253client # [6727713.554372] client systemd[1]: Started data mesher daemon.254client # [6727713.555746] client data-mesher[210]: time=2026-08-25T20:12:19.608Z level=INFO msg="starting expired-file sweeper" interval=1m0s255client # [6727713.556209] client systemd[1]: Starting Unbound recursive Domain Name Server...256client # [6727713.652628] client data-mesher[210]: time=2026-08-25T20:12:19.705Z level=INFO msg="received state sync from peer" peer=12D3KooWHPoP8vedGqWDJukeAXLQpcpVW93VyPrUMJ49bXEpWAr3257client # [6727713.652628] client data-mesher[210]: time=2026-08-25T20:12:19.705Z level=INFO msg="merging remote state" peer=12D3KooWHPoP8vedGqWDJukeAXLQpcpVW93VyPrUMJ49bXEpWAr3258server # [6727714.380603] server unbound-pre-start[280]: Root anchor updated!259client # [6727714.294230] client unbound-pre-start[272]: Root anchor updated!260server # [6727714.391382] server unbound-pre-start[284]: setup in directory /var/lib/unbound261client # [6727714.305226] client unbound-pre-start[276]: setup in directory /var/lib/unbound262server # [6727715.336034] server unbound-pre-start[293]: Certificate request self-signature ok263server # [6727715.336034] server unbound-pre-start[293]: subject=CN=unbound-control264server # [6727715.356245] server unbound-pre-start[284]: removing artifacts265server # [6727715.357870] server unbound-pre-start[284]: Setup success. Certificates created. Enable in unbound.conf file to use266client # [6727715.432858] client unbound-pre-start[285]: Certificate request self-signature ok267client # [6727715.432858] client unbound-pre-start[285]: subject=CN=unbound-control268client # [6727715.452350] client unbound-pre-start[276]: removing artifacts269client # [6727715.454231] client unbound-pre-start[276]: Setup success. Certificates created. Enable in unbound.conf file to use270client # [6727716.112073] client unbound[290]: [290:0] notice: init module 0: validator271client # [6727716.112201] client unbound[290]: [290:0] notice: init module 1: iterator272client # [6727716.118358] client unbound[290]: [290:0] info: start of service (unbound 1.25.2).273client # [6727716.118494] client systemd[1]: Started Unbound recursive Domain Name Server.274server # [6727716.115332] server unbound[298]: [298:0] notice: init module 0: validator275client # [6727716.118771] client systemd[1]: Reached target Multi-User System.276server # [6727716.115449] server unbound[298]: [298:0] notice: init module 1: iterator277client # [6727716.118884] client systemd[1]: Reached target Host and Network Name Lookups.278server # [6727716.121857] server unbound[298]: [298:0] info: start of service (unbound 1.25.2).279client # [6727716.120289] client systemd[1]: Starting Reload unbound zone configuration...280client # [6727716.177461] client unbound[290]: [290:0] info: service stopped (unbound 1.25.2).281client # [6727716.178049] client unbound-control[293]: ok282client # [6727716.178046] 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 ratelimiting283client # [6727716.178053] client unbound[290]: [290:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0284client # [6727716.179014] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.285client # [6727716.179206] client systemd[1]: Finished Reload unbound zone configuration.286client # [6727716.179552] client systemd[1]: Startup finished in 17.586s.287client # [6727716.180106] client unbound[290]: [290:0] notice: Restart of unbound 1.25.2.288client # [6727716.181050] client unbound[290]: [290:0] notice: init module 0: validator289client # [6727716.181113] client unbound[290]: [290:0] notice: init module 1: iterator290client # [6727716.186120] client unbound[290]: [290:0] info: start of service (unbound 1.25.2).291server # [6727716.122015] server systemd[1]: Started Unbound recursive Domain Name Server.292server # [6727716.122299] server systemd[1]: Reached target Multi-User System.293server # [6727716.122427] server systemd[1]: Reached target Host and Network Name Lookups.294server # [6727716.123815] server systemd[1]: Starting Reload unbound zone configuration...295server # [6727716.177266] server unbound[298]: [298:0] info: service stopped (unbound 1.25.2).296server # [6727716.177590] server unbound-control[301]: ok297server # [6727716.177711] 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 ratelimiting298server # [6727716.177716] server unbound[298]: [298:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0299server # [6727716.179571] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.300server # [6727716.179784] server systemd[1]: Finished Reload unbound zone configuration.301server # [6727716.179791] server unbound[298]: [298:0] notice: Restart of unbound 1.25.2.302server # [6727716.180311] server systemd[1]: Startup finished in 17.560s.303server # [6727716.180799] server unbound[298]: [298:0] notice: init module 0: validator304server # [6727716.180872] server unbound[298]: [298:0] notice: init module 1: iterator305server # [6727716.186029] server unbound[298]: [298:0] info: start of service (unbound 1.25.2).306server: (finished: waiting for unit unbound.service, in 18.69 seconds)307client: waiting for unit unbound.service308client: (finished: waiting for unit unbound.service, in 0.03 seconds)309server: waiting for unit data-mesher.service310server: (finished: waiting for unit data-mesher.service, in 0.01 seconds)311server: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1312server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1, in 0.03 seconds)313server: must succeed: data-mesher file update --network-id /nix/store/f5rlk42m51jyn1i1w1ja61hwdbvzisk1-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/cnames314server: (finished: must succeed: data-mesher file update --network-id /nix/store/f5rlk42m51jyn1i1w1ja61hwdbvzisk1-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)315??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.316 File "/nix/store/8xlk88ia8b5yg9kfrg3skndwzgphipvr-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39317server: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test318??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.319 File "/nix/store/8xlk88ia8b5yg9kfrg3skndwzgphipvr-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39320server # [6727716.807353] server systemd[1]: Starting Reload unbound zone configuration...321server # [6727716.810936] server data-mesher[219]: time=2026-08-25T20:12:22.863Z level=INFO msg=http_request uri=/files/dns/cnames status=204322server # [6727716.903730] server unbound[298]: [298:0] info: service stopped (unbound 1.25.2).323server # [6727716.904081] server unbound-control[337]: ok324server # [6727716.904359] 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 ratelimiting325server # [6727716.904365] server unbound[298]: [298:0] info: server stats for thread 0: requestlist max 2 avg 1.33333 exceeded 0 jostled 0326server # [6727716.905923] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.327server # [6727716.906172] server systemd[1]: Finished Reload unbound zone configuration.328server # [6727716.906235] server unbound[298]: [298:0] notice: Restart of unbound 1.25.2.329server # [6727716.907484] server unbound[298]: [298:0] notice: init module 0: validator330server # [6727716.907556] server unbound[298]: [298:0] notice: init module 1: iterator331server # [6727716.912320] server unbound[298]: [298:0] info: start of service (unbound 1.25.2).332server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test, in 1.05 seconds)333(finished: run the VM test script, in 19.85 seconds)334test script finished in 20.36s335cleanup336kill NspawnMachine (pid 52)337kill NspawnMachine (pid 53)338Container client terminated by signal KILL.339Container server terminated by signal KILL.340(finished: cleanup, in 0.50 seconds)