container-test-run-dm-dns
checks.aarch64-linux.dm-dns
· build #524
· 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(client): TAP vde-tap1 not found; container will be isolated from VDE19nixos-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.20nixos-nspawn(server): TAP vde-tap1 not found; container will be isolated from VDE21nixos-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.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 client on /build/vm-state-client.25░ Spawning container server on /build/vm-state-server.26client # [7056646.899612] client systemd-journald[87]: Journal started27client # [7056646.899660] client systemd-journald[87]: Runtime Journal (/run/log/journal/ebb04a4263ae4f01bad88023a9c381c0) is 8M, max 2.5G, 2.4G free.28client # [7056646.902869] client systemd[1]: Finished Create Static Device Nodes in /dev gracefully.29client # [7056646.910101] client systemd[1]: Starting Flush Journal to Persistent Storage...30client # [7056646.911168] client systemd[1]: Starting Network Name Resolution...31client # [7056646.911885] client systemd[1]: Starting Create Static Device Nodes in /dev...32client # [7056646.920357] client systemd-journald[87]: Time spent on flushing to /var/log/journal/ebb04a4263ae4f01bad88023a9c381c0 is 1.448ms for 6 entries.33client # [7056646.920357] client systemd-journald[87]: System Journal (/var/log/journal/ebb04a4263ae4f01bad88023a9c381c0) is 8M, max 4G, 3.9G free.34client # [7056646.927069] client systemd[1]: Finished Create Static Device Nodes in /dev.35client # [7056646.927279] client systemd[1]: Reached target Preparation for Local File Systems.36client # [7056646.927360] client systemd[1]: Reached target Local File Systems.37client # [7056646.928082] client systemd[1]: Listening on Boot Loader Control Service Socket.38client # [7056646.928124] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container39client # [7056646.928926] client systemd[1]: Starting Save Transient machine-id to Disk...40client # [7056646.928956] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys41client # [7056646.945848] client systemd[1]: Finished Flush Journal to Persistent Storage.42client # [7056646.947449] client systemd[1]: Starting Create System Files and Directories...43client # [7056646.965803] client systemd-tmpfiles[132]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted44client # [7056646.965999] client systemd-tmpfiles[132]: fchmod() of /var/log/journal failed: Operation not permitted45client # [7056646.966135] client systemd-tmpfiles[132]: fchmod() of /var/log/journal/ebb04a4263ae4f01bad88023a9c381c0 failed: Operation not permitted46client # [7056646.966349] client systemd-tmpfiles[132]: fchmod() of /run/log/journal failed: Operation not permitted47client # [7056646.967706] client systemd[1]: Finished Create System Files and Directories.48client # [7056646.968767] client systemd[1]: Starting Rebuild Journal Catalog...49client # [7056646.969465] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...50client # [7056646.982933] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.51client # [7056646.987749] client systemd[1]: Finished Rebuild Journal Catalog.52client # [7056646.988797] client systemd[1]: Starting Update is Completed...53client # [7056646.999639] client systemd[1]: Finished Update is Completed.54server # [7056646.935744] server systemd-journald[96]: Journal started55server # [7056646.935802] server systemd-journald[96]: Runtime Journal (/run/log/journal/ff87a10cfb7c44a2bf19c1f2e6b62e87) is 8M, max 2.5G, 2.4G free.56server # [7056646.940830] server systemd[1]: Starting Flush Journal to Persistent Storage...57server # [7056646.941618] server systemd[1]: Starting Network Name Resolution...58server # [7056646.942317] server systemd[1]: Starting Create Static Device Nodes in /dev...59server # [7056646.951647] server systemd-journald[96]: Time spent on flushing to /var/log/journal/ff87a10cfb7c44a2bf19c1f2e6b62e87 is 1.716ms for 5 entries.60server # [7056646.951647] server systemd-journald[96]: System Journal (/var/log/journal/ff87a10cfb7c44a2bf19c1f2e6b62e87) is 8M, max 4G, 3.9G free.61server # [7056646.957621] server systemd[1]: Finished Create Static Device Nodes in /dev.62server # [7056646.957840] server systemd[1]: Reached target Preparation for Local File Systems.63server # [7056646.957929] server systemd[1]: Reached target Local File Systems.64server # [7056646.958652] server systemd[1]: Listening on Boot Loader Control Service Socket.65server # [7056646.958695] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container66server # [7056646.959540] server systemd[1]: Starting Save Transient machine-id to Disk...67server # [7056646.959571] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys68server # [7056646.965224] server systemd[1]: Finished Flush Journal to Persistent Storage.69server # [7056646.966703] server systemd[1]: Starting Create System Files and Directories...70server # [7056646.984677] server systemd-tmpfiles[136]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted71server # [7056646.984885] server systemd-tmpfiles[136]: fchmod() of /var/log/journal failed: Operation not permitted72server # [7056646.985029] server systemd-tmpfiles[136]: fchmod() of /var/log/journal/ff87a10cfb7c44a2bf19c1f2e6b62e87 failed: Operation not permitted73server # [7056646.985246] server systemd-tmpfiles[136]: fchmod() of /run/log/journal failed: Operation not permitted74server # [7056646.986747] server systemd[1]: Finished Create System Files and Directories.75server # [7056646.987737] server systemd[1]: Starting Rebuild Journal Catalog...76server # [7056646.988446] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...77server # [7056647.001552] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.78server # [7056647.010058] server systemd[1]: Finished Rebuild Journal Catalog.79server # [7056647.011079] server systemd[1]: Starting Update is Completed...80server # [7056647.021432] server systemd[1]: Finished Update is Completed.81client # [7056647.066321] client systemd[1]: Finished Firewall.82client # [7056647.066469] client systemd[1]: Reached target Preparation for Network.83client # [7056647.066681] client systemd[1]: Listening on Network Management Resolve Hook Socket.84client # [7056647.067778] client systemd[1]: Starting Network Management...85server # [7056647.092334] server systemd[1]: Finished Firewall.86server # [7056647.092481] server systemd[1]: Reached target Preparation for Network.87server # [7056647.092686] server systemd[1]: Listening on Network Management Resolve Hook Socket.88server # [7056647.093819] server systemd[1]: Starting Network Management...89client # [7056647.424922] client systemd-networkd[204]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted90client # [7056647.425013] client systemd-networkd[204]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted91client # [7056647.431484] client systemd-networkd[204]: /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.92client # [7056647.431648] client systemd-networkd[204]: /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.93client # [7056647.431811] client systemd-networkd[204]: lo: Link UP94client # [7056647.431817] client systemd-networkd[204]: lo: Gained carrier95client # [7056647.432020] client systemd-networkd[204]: eth1: Configuring with /etc/systemd/network/40-eth1.network.96client # [7056647.432397] client systemd[1]: Started Network Management.97client # [7056647.432476] client systemd-networkd[204]: eth1: Link UP98client # [7056647.432807] client systemd-networkd[204]: eth1: Gained carrier99client # [7056647.433457] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd...100client # [7056647.492082] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd.101client # [7056647.524101] client systemd[1]: Finished Save Transient machine-id to Disk.102client # [7056647.538509] client systemd-resolved[107]: Positive Trust Anchors:103client # [7056647.538523] client systemd-resolved[107]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d104client # [7056647.538525] client systemd-resolved[107]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16105client # [7056647.538562] client systemd-resolved[107]: 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 test106client # [7056647.560505] client systemd-resolved[107]: Using system hostname 'client'.107client # [7056647.562046] client systemd[1]: Started Network Name Resolution.108client # [7056647.562117] client systemd[1]: Reached target Network.109client # [7056647.562188] client systemd[1]: Reached target System Initialization.110client # [7056647.562266] client systemd[1]: Started Watch for zone file changes.111client # [7056647.562301] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container112client # [7056647.562322] client systemd[1]: Started Daily Cleanup of Temporary Directories.113client # [7056647.562341] client systemd[1]: Reached target Path Units.114client # [7056647.562371] client systemd[1]: Reached target Timer Units.115client # [7056647.562481] client systemd[1]: Listening on D-Bus System Message Bus Socket.116client # [7056647.562583] client systemd[1]: Listening on Nix Daemon Socket.117client # [7056647.562686] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.118client # [7056647.562707] client systemd[1]: Reached target Socket Units.119client # [7056647.562743] client systemd[1]: Reached target Basic System.120client # [7056647.564262] client systemd[1]: Starting data mesher daemon...121client # [7056647.564990] client systemd[1]: Starting Import lastlog data into lastlog2 database...122client # [7056647.565738] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...123client # [7056647.566985] client systemd[1]: Starting D-Bus System Message Bus...124client # [7056647.586250] client systemd[1]: Finished Import lastlog data into lastlog2 database.125client # [7056647.663994] client nsncd[212]: Aug 29 15:34:33.717 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"126client # [7056647.664152] client systemd[1]: Started Name Service Cache Daemon (nsncd).127client # [7056647.664252] client systemd[1]: Reached target User and Group Name Lookups.128client # [7056647.666348] client systemd[1]: Starting User Login Management...129client # [7056647.667717] client systemd[1]: Starting Permit User Sessions...130server # [7056647.458536] server systemd-networkd[213]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted131server # [7056647.458627] server systemd-networkd[213]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted132server # [7056647.465080] 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.133server # [7056647.465241] 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.134server # [7056647.465399] server systemd-networkd[213]: lo: Link UP135server # [7056647.465402] server systemd-networkd[213]: lo: Gained carrier136server # [7056647.465595] server systemd-networkd[213]: eth1: Configuring with /etc/systemd/network/40-eth1.network.137server # [7056647.465964] server systemd[1]: Started Network Management.138server # [7056647.484617] server systemd-networkd[213]: eth1: Link UP139server # [7056647.484659] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...140server # [7056647.484887] server systemd-networkd[213]: eth1: Gained carrier141server # [7056647.525544] server systemd[1]: Finished Save Transient machine-id to Disk.142server # [7056647.529740] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.143server # [7056647.575873] server systemd-resolved[116]: Positive Trust Anchors:144server # [7056647.575884] server systemd-resolved[116]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d145server # [7056647.575889] server systemd-resolved[116]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16146server # [7056647.575944] server 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 test147server # [7056647.598462] server systemd-resolved[116]: Using system hostname 'server'.148server # [7056647.599850] server systemd[1]: Started Network Name Resolution.149server # [7056647.599922] server systemd[1]: Reached target Network.150server # [7056647.599992] server systemd[1]: Reached target System Initialization.151server # [7056647.600088] server systemd[1]: Started Watch for zone file changes.152server # [7056647.600116] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container153server # [7056647.600139] server systemd[1]: Started Daily Cleanup of Temporary Directories.154server # [7056647.600155] server systemd[1]: Reached target Path Units.155server # [7056647.600189] server systemd[1]: Reached target Timer Units.156server # [7056647.600310] server systemd[1]: Listening on D-Bus System Message Bus Socket.157server # [7056647.600422] server systemd[1]: Listening on Nix Daemon Socket.158server # [7056647.600532] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.159server # [7056647.600555] server systemd[1]: Reached target Socket Units.160server # [7056647.600586] server systemd[1]: Reached target Basic System.161server # [7056647.601732] server systemd[1]: Starting data mesher daemon...162server # [7056647.602461] server systemd[1]: Starting Import lastlog data into lastlog2 database...163server # [7056647.603183] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...164server # [7056647.604548] server systemd[1]: Starting D-Bus System Message Bus...165server # [7056647.624855] server systemd[1]: Finished Import lastlog data into lastlog2 database.166server # [7056647.698489] server nsncd[221]: Aug 29 15:34:33.751 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"167server # [7056647.698579] server systemd[1]: Started Name Service Cache Daemon (nsncd).168server # [7056647.698638] server systemd[1]: Reached target User and Group Name Lookups.169server # [7056647.717164] server systemd[1]: Starting User Login Management...170client # [7056647.723392] client systemd[1]: Finished Permit User Sessions.171client # [7056647.724635] client systemd[1]: Started Console Getty.172client # [7056647.724685] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0173client # [7056647.724708] client systemd[1]: Reached target Login Prompts.174client # [7056647.854217] client dbus-broker-launch[213]: Looking up NSS user entry for 'systemd-timesync'...175client # [7056647.854950] client dbus-broker-launch[213]: NSS returned no entry for 'systemd-timesync'176client # [7056647.854950] client dbus-broker-launch[213]: Invalid user-name in /nix/store/giqgsa6vjp02ngnhasy010jgsrrlrx1x-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"177client # [7056647.855350] client systemd[1]: Started D-Bus System Message Bus.178client # [7056647.864458] client dbus-broker-launch[213]: Ready179client # [7056647.890170] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.180server # [7056647.718903] server systemd[1]: Starting Permit User Sessions...181server # [7056647.729379] server systemd[1]: Finished Permit User Sessions.182server # [7056647.730490] server systemd[1]: Started Console Getty.183server # [7056647.730543] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0184server # [7056647.730569] server systemd[1]: Reached target Login Prompts.185server # [7056647.822968] server dbus-broker-launch[222]: Looking up NSS user entry for 'systemd-timesync'...186server # [7056647.823881] server dbus-broker-launch[222]: NSS returned no entry for 'systemd-timesync'187server # [7056647.823932] server dbus-broker-launch[222]: Invalid user-name in /nix/store/8w5s9v175d1kxcvfs6lp43972ni20lqb-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"188server # [7056647.824360] server systemd[1]: Started D-Bus System Message Bus.189server # [7056647.832096] server dbus-broker-launch[222]: Ready190server # [7056647.919154] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.191server # [7056648.080290] server data-mesher[219]: time=2026-08-29T15:34:34.133Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]192server # [7056648.081329] server data-mesher[219]: time=2026-08-29T15:34:34.134Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWMBjdvg1RvEKmjMuedbQg7wabqhJSpVaB6hAc8pucRK9S: [/dns/client.test/tcp/7946]} {12D3KooWKMCHbGV4FkNjkUWvJfMiZNiJXvjwtdmEiDgkW9cAUES1: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWKMCHbGV4FkNjkUWvJfMiZNiJXvjwtdmEiDgkW9cAUES1193server # [7056648.081373] server data-mesher[219]: time=2026-08-29T15:34:34.134Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml194server # [7056648.082634] server data-mesher[219]: time=2026-08-29T15:34:34.135Z level=INFO msg="checking file integrity"195server # [7056648.082734] server data-mesher[219]: time=2026-08-29T15:34:34.135Z level=INFO msg="file integrity check complete"196server # [7056648.086697] server data-mesher[219]: time=2026-08-29T15:34:34.139Z level=INFO msg="libp2p host created" peer_id=12D3KooWKMCHbGV4FkNjkUWvJfMiZNiJXvjwtdmEiDgkW9cAUES1 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]"197server # [7056648.086734] server data-mesher[219]: time=2026-08-29T15:34:34.139Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name198server # [7056648.086734] server data-mesher[219]: time=2026-08-29T15:34:34.139Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name199server # [7056648.086734] server data-mesher[219]: time=2026-08-29T15:34:34.139Z level=INFO msg="registered HTTP route" method=GET path=/files200server # [7056648.086734] server data-mesher[219]: time=2026-08-29T15:34:34.139Z level=INFO msg="starting server"201server # [7056648.086908] server data-mesher[219]: time=2026-08-29T15:34:34.140Z level=INFO msg="waiting for DHT to populate" delay=10s202server # [7056648.086935] server data-mesher[219]: time=2026-08-29T15:34:34.140Z level=INFO msg="HTTP server listening" address=[::1]:7331203server # [7056648.086961] server data-mesher[219]: time=2026-08-29T15:34:34.140Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331204server # [7056648.091208] server data-mesher[219]: time=2026-08-29T15:34:34.144Z level=INFO msg="peer connected" peer_id=12D3KooWMBjdvg1RvEKmjMuedbQg7wabqhJSpVaB6hAc8pucRK9S remote_addr=/ip4/192.168.1.1/tcp/7946205server # [7056648.160478] server systemd-logind[239]: New seat seat0.206server # [7056648.160606] server systemd[1]: Started User Login Management.207server # [7056648.161701] server systemd[1]: Starting linger-users.service...208server # [7056648.172190] server systemd[1]: linger-users.service: Deactivated successfully.209server # [7056648.172478] server systemd[1]: Finished linger-users.service.210client # [7056648.031206] client data-mesher[210]: time=2026-08-29T15:34:34.084Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]211client # [7056648.032291] client data-mesher[210]: time=2026-08-29T15:34:34.085Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWMBjdvg1RvEKmjMuedbQg7wabqhJSpVaB6hAc8pucRK9S: [/dns/client.test/tcp/7946]} {12D3KooWKMCHbGV4FkNjkUWvJfMiZNiJXvjwtdmEiDgkW9cAUES1: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWMBjdvg1RvEKmjMuedbQg7wabqhJSpVaB6hAc8pucRK9S212client # [7056648.032337] client data-mesher[210]: time=2026-08-29T15:34:34.085Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml213client # [7056648.043474] client data-mesher[210]: time=2026-08-29T15:34:34.096Z level=INFO msg="checking file integrity"214client # [7056648.043591] client data-mesher[210]: time=2026-08-29T15:34:34.096Z level=INFO msg="file integrity check complete"215client # [7056648.047721] client data-mesher[210]: time=2026-08-29T15:34:34.100Z level=INFO msg="libp2p host created" peer_id=12D3KooWMBjdvg1RvEKmjMuedbQg7wabqhJSpVaB6hAc8pucRK9S 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]"216client # [7056648.047809] client data-mesher[210]: time=2026-08-29T15:34:34.100Z level=INFO msg="registered HTTP route" method=GET path=/files217client # [7056648.047809] client data-mesher[210]: time=2026-08-29T15:34:34.100Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name218client # [7056648.047809] client data-mesher[210]: time=2026-08-29T15:34:34.100Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name219client # [7056648.047809] client data-mesher[210]: time=2026-08-29T15:34:34.100Z level=INFO msg="starting server"220client # [7056648.047907] client data-mesher[210]: time=2026-08-29T15:34:34.101Z level=INFO msg="waiting for DHT to populate" delay=10s221client # [7056648.047952] client data-mesher[210]: time=2026-08-29T15:34:34.101Z level=INFO msg="HTTP server listening" address=[::1]:7331222client # [7056648.047981] client data-mesher[210]: time=2026-08-29T15:34:34.101Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331223client # [7056648.091936] client data-mesher[210]: time=2026-08-29T15:34:34.145Z level=INFO msg="peer connected" peer_id=12D3KooWKMCHbGV4FkNjkUWvJfMiZNiJXvjwtdmEiDgkW9cAUES1 remote_addr=/ip4/192.168.1.2/tcp/7946224client # [7056648.176037] client systemd-logind[230]: New seat seat0.225client # [7056648.176217] client systemd[1]: Started User Login Management.226client # [7056648.177330] client systemd[1]: Starting linger-users.service...227client # [7056648.187524] client systemd[1]: linger-users.service: Deactivated successfully.228client # [7056648.187675] client systemd[1]: Finished linger-users.service.229client # [7056648.484210] client systemd-networkd[204]: eth1: Gained IPv6LL230server # [7056648.932228] server systemd-networkd[213]: eth1: Gained IPv6LL231server: still waiting for container 'server' to reach ready state...232server # [7056658.048868] server data-mesher[219]: time=2026-08-29T15:34:44.101Z level=INFO msg="received state sync from peer" peer=12D3KooWMBjdvg1RvEKmjMuedbQg7wabqhJSpVaB6hAc8pucRK9S233server # [7056658.048868] server data-mesher[219]: time=2026-08-29T15:34:44.102Z level=INFO msg="merging remote state" peer=12D3KooWMBjdvg1RvEKmjMuedbQg7wabqhJSpVaB6hAc8pucRK9S234server # [7056658.087629] server data-mesher[219]: time=2026-08-29T15:34:44.140Z level=INFO msg="performing state exchange with peers on join" count=1235server # [7056658.087707] server data-mesher[219]: time=2026-08-29T15:34:44.140Z level=DEBUG msg="initiating state exchange" peer=12D3KooWMBjdvg1RvEKmjMuedbQg7wabqhJSpVaB6hAc8pucRK9S timeout=5s236server # [7056658.088479] server data-mesher[219]: time=2026-08-29T15:34:44.141Z level=INFO msg="merging remote state" peer=12D3KooWMBjdvg1RvEKmjMuedbQg7wabqhJSpVaB6hAc8pucRK9S237server # [7056658.088479] server data-mesher[219]: time=2026-08-29T15:34:44.141Z level=INFO msg="state exchange complete" peer=12D3KooWMBjdvg1RvEKmjMuedbQg7wabqhJSpVaB6hAc8pucRK9S timeout=5s238server # [7056658.088549] server data-mesher[219]: time=2026-08-29T15:34:44.141Z level=INFO msg="server started"239server # [7056658.088725] server data-mesher[219]: time=2026-08-29T15:34:44.141Z level=INFO msg="starting expired-file sweeper" interval=1m0s240server # [7056658.088796] server systemd[1]: Started data mesher daemon.241server # [7056658.091160] server systemd[1]: Starting Unbound recursive Domain Name Server...242client # [7056658.048142] client data-mesher[210]: time=2026-08-29T15:34:44.101Z level=INFO msg="performing state exchange with peers on join" count=1243client # [7056658.048604] client data-mesher[210]: time=2026-08-29T15:34:44.101Z level=DEBUG msg="initiating state exchange" peer=12D3KooWKMCHbGV4FkNjkUWvJfMiZNiJXvjwtdmEiDgkW9cAUES1 timeout=5s244client # [7056658.049053] client data-mesher[210]: time=2026-08-29T15:34:44.102Z level=INFO msg="merging remote state" peer=12D3KooWKMCHbGV4FkNjkUWvJfMiZNiJXvjwtdmEiDgkW9cAUES1245client # [7056658.049053] client data-mesher[210]: time=2026-08-29T15:34:44.102Z level=INFO msg="state exchange complete" peer=12D3KooWKMCHbGV4FkNjkUWvJfMiZNiJXvjwtdmEiDgkW9cAUES1 timeout=5s246client # [7056658.049125] client data-mesher[210]: time=2026-08-29T15:34:44.102Z level=INFO msg="server started"247client # [7056658.049193] client data-mesher[210]: time=2026-08-29T15:34:44.102Z level=INFO msg="starting expired-file sweeper" interval=1m0s248client # [7056658.049365] client systemd[1]: Started data mesher daemon.249client # [7056658.051798] client systemd[1]: Starting Unbound recursive Domain Name Server...250client # [7056658.088216] client data-mesher[210]: time=2026-08-29T15:34:44.141Z level=INFO msg="received state sync from peer" peer=12D3KooWKMCHbGV4FkNjkUWvJfMiZNiJXvjwtdmEiDgkW9cAUES1251client # [7056658.088216] client data-mesher[210]: time=2026-08-29T15:34:44.141Z level=INFO msg="merging remote state" peer=12D3KooWKMCHbGV4FkNjkUWvJfMiZNiJXvjwtdmEiDgkW9cAUES1252server # [7056658.570612] server unbound-pre-start[284]: Root anchor updated!253server # [7056658.585048] server unbound-pre-start[288]: setup in directory /var/lib/unbound254client # [7056658.570691] client unbound-pre-start[272]: Root anchor updated!255client # [7056658.585133] client unbound-pre-start[276]: setup in directory /var/lib/unbound256server # [7056659.373652] server unbound-pre-start[297]: Certificate request self-signature ok257server # [7056659.373652] server unbound-pre-start[297]: subject=CN=unbound-control258server # [7056659.391021] server unbound-pre-start[288]: removing artifacts259server # [7056659.392649] server unbound-pre-start[288]: Setup success. Certificates created. Enable in unbound.conf file to use260client # [7056659.637239] client unbound-pre-start[285]: Certificate request self-signature ok261client # [7056659.637239] client unbound-pre-start[285]: subject=CN=unbound-control262client # [7056659.657106] client unbound-pre-start[276]: removing artifacts263client # [7056659.658781] client unbound-pre-start[276]: Setup success. Certificates created. Enable in unbound.conf file to use264server # [7056659.919388] server unbound[302]: [302:0] notice: init module 0: validator265server # [7056659.919500] server unbound[302]: [302:0] notice: init module 1: iterator266server # [7056659.925282] server unbound[302]: [302:0] info: start of service (unbound 1.26.0).267server # [7056659.925445] server systemd[1]: Started Unbound recursive Domain Name Server.268server # [7056659.925940] server systemd[1]: Reached target Multi-User System.269server # [7056659.926206] server systemd[1]: Reached target Host and Network Name Lookups.270server # [7056659.927938] server systemd[1]: Starting Reload unbound zone configuration...271server # [7056659.971502] server unbound[302]: [302:0] info: service stopped (unbound 1.26.0).272server # [7056659.971745] server unbound-control[305]: ok273server # [7056659.971861] server unbound[302]: [302:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting274server # [7056659.971865] server unbound[302]: [302:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0275server # [7056659.972374] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.276server # [7056659.972509] server systemd[1]: Finished Reload unbound zone configuration.277server # [7056659.972735] server systemd[1]: Startup finished in 13.432s.278server # [7056659.973645] server unbound[302]: [302:0] notice: Restart of unbound 1.26.0.279server # [7056659.974640] server unbound[302]: [302:0] notice: init module 0: validator280server # [7056659.974702] server unbound[302]: [302:0] notice: init module 1: iterator281server # [7056659.979242] server unbound[302]: [302:0] info: start of service (unbound 1.26.0).282server: (finished: waiting for unit unbound.service, in 14.17 seconds)283client: waiting for unit unbound.service284client: (finished: waiting for unit unbound.service, in 0.17 seconds)285server: waiting for unit data-mesher.service286server: (finished: waiting for unit data-mesher.service, in 0.01 seconds)287server: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1288server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1, in 0.02 seconds)289server: must succeed: data-mesher file update --network-id /nix/store/msmhl5dsf2vjmg34h0hwdmynk8vgn91h-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/cnames290server: (finished: must succeed: data-mesher file update --network-id /nix/store/msmhl5dsf2vjmg34h0hwdmynk8vgn91h-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)291??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.292 File "/nix/store/5ji70zizd2wdp8kz2n2hzzcabdw71fwn-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39293server: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test294??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.295 File "/nix/store/5ji70zizd2wdp8kz2n2hzzcabdw71fwn-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39296client # [7056660.239317] client unbound[290]: [290:0] notice: init module 0: validator297client # [7056660.239438] client unbound[290]: [290:0] notice: init module 1: iterator298client # [7056660.245203] client unbound[290]: [290:0] info: start of service (unbound 1.26.0).299client # [7056660.245342] client systemd[1]: Started Unbound recursive Domain Name Server.300client # [7056660.245643] client systemd[1]: Reached target Multi-User System.301client # [7056660.245790] client systemd[1]: Reached target Host and Network Name Lookups.302client # [7056660.247235] client systemd[1]: Starting Reload unbound zone configuration...303client # [7056660.283906] client unbound[290]: [290:0] info: service stopped (unbound 1.26.0).304client # [7056660.284201] client unbound-control[293]: ok305client # [7056660.284269] 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 ratelimiting306client # [7056660.284275] client unbound[290]: [290:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0307client # [7056660.285785] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.308client # [7056660.286007] client unbound[290]: [290:0] notice: Restart of unbound 1.26.0.309client # [7056660.286093] client systemd[1]: Finished Reload unbound zone configuration.310client # [7056660.286614] client systemd[1]: Startup finished in 13.761s.311client # [7056660.286878] client unbound[290]: [290:0] notice: init module 0: validator312client # [7056660.286937] client unbound[290]: [290:0] notice: init module 1: iterator313client # [7056660.291620] client unbound[290]: [290:0] info: start of service (unbound 1.26.0).314server # [7056660.435850] server data-mesher[219]: time=2026-08-29T15:34:46.488Z level=INFO msg=http_request uri=/files/dns/cnames status=204315server # [7056660.436103] server systemd[1]: Starting Reload unbound zone configuration...316server # [7056660.481281] server unbound[302]: [302:0] info: service stopped (unbound 1.26.0).317server # [7056660.481607] server unbound-control[341]: ok318server # [7056660.481754] server unbound[302]: [302:0] info: server stats for thread 0: 5 queries, 2 answers from cache, 3 recursions, 0 prefetch, 0 rejected by ip ratelimiting319server # [7056660.481762] server unbound[302]: [302:0] info: server stats for thread 0: requestlist max 2 avg 1.33333 exceeded 0 jostled 0320server # [7056660.482841] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.321server # [7056660.483112] server systemd[1]: Finished Reload unbound zone configuration.322server # [7056660.483351] server unbound[302]: [302:0] notice: Restart of unbound 1.26.0.323server # [7056660.484553] server unbound[302]: [302:0] notice: init module 0: validator324server # [7056660.484629] server unbound[302]: [302:0] notice: init module 1: iterator325server # [7056660.490705] server unbound[302]: [302:0] info: start of service (unbound 1.26.0).326server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test, in 1.05 seconds)327(finished: run the VM test script, in 15.46 seconds)328test script finished in 15.51s329cleanup330kill NspawnMachine (pid 52)331kill NspawnMachine (pid 53)332Container client terminated by signal KILL.333(finished: cleanup, in 0.33 seconds)334Container server terminated by signal KILL.