container-test-run-dm-dns
checks.aarch64-linux.dm-dns
· build #511
· 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 VMs12server: systemd-nspawn running (pid 52)13client: systemd-nspawn running (pid 53)14server: Waiting for journal at /build/vm-state-server/var/log/journal...15client: Waiting for journal at /build/vm-state-client/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.26server # [6865765.583736] server systemd-journald[96]: Journal started27server # [6865765.583797] server systemd-journald[96]: Runtime Journal (/run/log/journal/a166f4acf0ef48a48a091cd6421629b7) is 8M, max 2.5G, 2.4G free.28server # [6865765.593428] server systemd[1]: Starting Flush Journal to Persistent Storage...29server # [6865765.594350] server systemd[1]: Starting Network Name Resolution...30server # [6865765.595024] server systemd[1]: Starting Create Static Device Nodes in /dev...31server # [6865765.604594] server systemd-journald[96]: Time spent on flushing to /var/log/journal/a166f4acf0ef48a48a091cd6421629b7 is 1.796ms for 5 entries.32server # [6865765.604594] server systemd-journald[96]: System Journal (/var/log/journal/a166f4acf0ef48a48a091cd6421629b7) is 8M, max 4G, 3.9G free.33server # [6865765.611570] server systemd[1]: Finished Create Static Device Nodes in /dev.34server # [6865765.611819] server systemd[1]: Reached target Preparation for Local File Systems.35server # [6865765.611921] server systemd[1]: Reached target Local File Systems.36server # [6865765.612820] server systemd[1]: Listening on Boot Loader Control Service Socket.37server # [6865765.612873] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container38server # [6865765.613743] server systemd[1]: Starting Save Transient machine-id to Disk...39server # [6865765.613779] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys40server # [6865765.618222] server systemd[1]: Finished Flush Journal to Persistent Storage.41server # [6865765.619525] server systemd[1]: Starting Create System Files and Directories...42server # [6865765.636516] server systemd-tmpfiles[137]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted43server # [6865765.636766] server systemd-tmpfiles[137]: fchmod() of /var/log/journal failed: Operation not permitted44server # [6865765.636935] server systemd-tmpfiles[137]: fchmod() of /var/log/journal/a166f4acf0ef48a48a091cd6421629b7 failed: Operation not permitted45server # [6865765.637201] server systemd-tmpfiles[137]: fchmod() of /run/log/journal failed: Operation not permitted46server # [6865765.638752] server systemd[1]: Finished Create System Files and Directories.47server # [6865765.639729] server systemd[1]: Starting Rebuild Journal Catalog...48server # [6865765.640403] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...49server # [6865765.653718] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.50server # [6865765.662160] server systemd[1]: Finished Rebuild Journal Catalog.51server # [6865765.663965] server systemd[1]: Starting Update is Completed...52server # [6865765.674803] server systemd[1]: Finished Update is Completed.53server # [6865765.681678] server systemd[1]: Finished Save Transient machine-id to Disk.54client # [6865765.583985] client systemd-journald[87]: Journal started55client # [6865765.584069] client systemd-journald[87]: Runtime Journal (/run/log/journal/eacc2023ff84476ea2588ce08d5d78b7) is 8M, max 2.5G, 2.4G free.56client # [6865765.586990] client systemd[1]: Starting Flush Journal to Persistent Storage...57client # [6865765.587815] client systemd[1]: Starting Network Name Resolution...58client # [6865765.588447] client systemd[1]: Starting Create Static Device Nodes in /dev...59client # [6865765.597692] client systemd-journald[87]: Time spent on flushing to /var/log/journal/eacc2023ff84476ea2588ce08d5d78b7 is 1.541ms for 5 entries.60client # [6865765.597692] client systemd-journald[87]: System Journal (/var/log/journal/eacc2023ff84476ea2588ce08d5d78b7) is 8M, max 4G, 3.9G free.61client # [6865765.604642] client systemd[1]: Finished Create Static Device Nodes in /dev.62client # [6865765.604878] client systemd[1]: Reached target Preparation for Local File Systems.63client # [6865765.604967] client systemd[1]: Reached target Local File Systems.64client # [6865765.605694] client systemd[1]: Listening on Boot Loader Control Service Socket.65client # [6865765.605737] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container66client # [6865765.606617] client systemd[1]: Starting Save Transient machine-id to Disk...67client # [6865765.606656] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys68client # [6865765.609335] client systemd[1]: Finished Flush Journal to Persistent Storage.69client # [6865765.610267] client systemd[1]: Starting Create System Files and Directories...70client # [6865765.629183] client systemd-tmpfiles[123]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted71client # [6865765.629494] client systemd-tmpfiles[123]: fchmod() of /var/log/journal failed: Operation not permitted72client # [6865765.629673] client systemd-tmpfiles[123]: fchmod() of /var/log/journal/eacc2023ff84476ea2588ce08d5d78b7 failed: Operation not permitted73client # [6865765.629952] client systemd-tmpfiles[123]: fchmod() of /run/log/journal failed: Operation not permitted74client # [6865765.631614] client systemd[1]: Finished Create System Files and Directories.75client # [6865765.632664] client systemd[1]: Starting Rebuild Journal Catalog...76client # [6865765.633336] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...77client # [6865765.645326] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.78client # [6865765.656643] client systemd[1]: Finished Rebuild Journal Catalog.79client # [6865765.657992] client systemd[1]: Starting Update is Completed...80client # [6865765.669032] client systemd[1]: Finished Update is Completed.81client # [6865765.682061] client systemd[1]: Finished Save Transient machine-id to Disk.82client # [6865765.745465] client systemd[1]: Finished Firewall.83client # [6865765.745602] client systemd[1]: Reached target Preparation for Network.84server # [6865765.742445] server systemd[1]: Finished Firewall.85client # [6865765.745887] client systemd[1]: Listening on Network Management Resolve Hook Socket.86server # [6865765.742600] server systemd[1]: Reached target Preparation for Network.87client # [6865765.747186] client systemd[1]: Starting Network Management...88server # [6865765.742801] server systemd[1]: Listening on Network Management Resolve Hook Socket.89server # [6865765.744021] server systemd[1]: Starting Network Management...90server # [6865766.197384] server systemd-networkd[214]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted91server # [6865766.197471] server systemd-networkd[214]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted92server # [6865766.204529] server systemd-networkd[214]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.93server # [6865766.204689] server systemd-networkd[214]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.94server # [6865766.204846] server systemd-networkd[214]: lo: Link UP95server # [6865766.204851] server systemd-networkd[214]: lo: Gained carrier96server # [6865766.205062] server systemd-networkd[214]: eth1: Configuring with /etc/systemd/network/40-eth1.network.97server # [6865766.205439] server systemd[1]: Started Network Management.98server # [6865766.205482] server systemd-networkd[214]: eth1: Link UP99server # [6865766.205733] server systemd-networkd[214]: eth1: Gained carrier100server # [6865766.206917] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...101server # [6865766.242430] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.102server # [6865766.306247] server systemd-resolved[117]: Positive Trust Anchors:103server # [6865766.306257] server systemd-resolved[117]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d104server # [6865766.306261] server systemd-resolved[117]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16105server # [6865766.306295] server systemd-resolved[117]: 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 # [6865766.328426] server systemd-resolved[117]: Using system hostname 'server'.107server # [6865766.329831] server systemd[1]: Started Network Name Resolution.108server # [6865766.329920] server systemd[1]: Reached target Network.109server # [6865766.330016] server systemd[1]: Reached target System Initialization.110server # [6865766.330130] server systemd[1]: Started Watch for zone file changes.111server # [6865766.330179] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container112server # [6865766.330213] server systemd[1]: Started Daily Cleanup of Temporary Directories.113server # [6865766.330245] server systemd[1]: Reached target Path Units.114server # [6865766.330298] server systemd[1]: Reached target Timer Units.115server # [6865766.330463] server systemd[1]: Listening on D-Bus System Message Bus Socket.116server # [6865766.330612] server systemd[1]: Listening on Nix Daemon Socket.117server # [6865766.330768] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.118server # [6865766.330801] server systemd[1]: Reached target Socket Units.119server # [6865766.330863] server systemd[1]: Reached target Basic System.120server # [6865766.388528] server systemd[1]: Starting data mesher daemon...121server # [6865766.389559] server systemd[1]: Starting Import lastlog data into lastlog2 database...122server # [6865766.390576] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...123server # [6865766.392104] server systemd[1]: Starting D-Bus System Message Bus...124server # [6865766.407775] server systemd[1]: Finished Import lastlog data into lastlog2 database.125server # [6865766.522459] server systemd[1]: Started Name Service Cache Daemon (nsncd).126server # [6865766.523824] server nsncd[221]: Aug 27 10:33:12.575 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"127server # [6865766.522534] server systemd[1]: Reached target User and Group Name Lookups.128client # [6865766.189609] client systemd-networkd[205]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted129client # [6865766.189701] client systemd-networkd[205]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted130client # [6865766.196821] client systemd-networkd[205]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.131client # [6865766.196982] client systemd-networkd[205]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.132client # [6865766.197151] client systemd-networkd[205]: lo: Link UP133client # [6865766.197154] client systemd-networkd[205]: lo: Gained carrier134client # [6865766.197344] client systemd-networkd[205]: eth1: Configuring with /etc/systemd/network/40-eth1.network.135client # [6865766.197774] client systemd[1]: Started Network Management.136client # [6865766.197823] client systemd-networkd[205]: eth1: Link UP137client # [6865766.198152] client systemd-networkd[205]: eth1: Gained carrier138client # [6865766.199414] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd...139client # [6865766.246779] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd.140client # [6865766.296844] client systemd-resolved[105]: Positive Trust Anchors:141client # [6865766.296855] client systemd-resolved[105]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d142client # [6865766.296859] client systemd-resolved[105]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16143client # [6865766.296894] client systemd-resolved[105]: 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 test144client # [6865766.319451] client systemd-resolved[105]: Using system hostname 'client'.145client # [6865766.320858] client systemd[1]: Started Network Name Resolution.146client # [6865766.320946] client systemd[1]: Reached target Network.147client # [6865766.321033] client systemd[1]: Reached target System Initialization.148client # [6865766.321137] client systemd[1]: Started Watch for zone file changes.149client # [6865766.321174] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container150client # [6865766.321205] client systemd[1]: Started Daily Cleanup of Temporary Directories.151client # [6865766.321229] client systemd[1]: Reached target Path Units.152client # [6865766.321269] client systemd[1]: Reached target Timer Units.153client # [6865766.321423] client systemd[1]: Listening on D-Bus System Message Bus Socket.154client # [6865766.321554] client systemd[1]: Listening on Nix Daemon Socket.155client # [6865766.321684] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.156client # [6865766.321711] client systemd[1]: Reached target Socket Units.157client # [6865766.321757] client systemd[1]: Reached target Basic System.158client # [6865766.323223] client systemd[1]: Starting data mesher daemon...159client # [6865766.324206] client systemd[1]: Starting Import lastlog data into lastlog2 database...160client # [6865766.325115] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...161client # [6865766.326547] client systemd[1]: Starting D-Bus System Message Bus...162client # [6865766.404654] client systemd[1]: Finished Import lastlog data into lastlog2 database.163server # [6865766.524308] server systemd[1]: Starting User Login Management...164server # [6865766.525389] server systemd[1]: Starting Permit User Sessions...165server # [6865766.572017] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.166server # [6865766.573329] server systemd[1]: Finished Permit User Sessions.167server # [6865766.574936] server systemd[1]: Started Console Getty.168server # [6865766.574982] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0169server # [6865766.575006] server systemd[1]: Reached target Login Prompts.170server # [6865766.685595] server dbus-broker-launch[222]: Looking up NSS user entry for 'systemd-timesync'...171server # [6865766.686434] server dbus-broker-launch[222]: NSS returned no entry for 'systemd-timesync'172server # [6865766.686434] server dbus-broker-launch[222]: Invalid user-name in /nix/store/45hn02i3sgq9z0biv7w0xgsp3jp3idwi-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"173server # [6865766.686885] server systemd[1]: Started D-Bus System Message Bus.174server # [6865766.694720] server dbus-broker-launch[222]: Ready175client # [6865766.536317] client nsncd[212]: Aug 27 10:33:12.589 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"176client # [6865766.536424] client systemd[1]: Started Name Service Cache Daemon (nsncd).177client # [6865766.536488] client systemd[1]: Reached target User and Group Name Lookups.178client # [6865766.560731] client systemd[1]: Starting User Login Management...179client # [6865766.561887] client systemd[1]: Starting Permit User Sessions...180client # [6865766.572099] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.181client # [6865766.573764] client systemd[1]: Finished Permit User Sessions.182client # [6865766.576806] client systemd[1]: Started Console Getty.183client # [6865766.576878] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0184client # [6865766.576913] client systemd[1]: Reached target Login Prompts.185client # [6865766.657638] client dbus-broker-launch[213]: Looking up NSS user entry for 'systemd-timesync'...186client # [6865766.658627] client dbus-broker-launch[213]: NSS returned no entry for 'systemd-timesync'187client # [6865766.658627] 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"188client # [6865766.659273] client systemd[1]: Started D-Bus System Message Bus.189client # [6865766.667960] client dbus-broker-launch[213]: Ready190server # [6865766.981003] server data-mesher[219]: time=2026-08-27T10:33:13.034Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]191server # [6865766.982085] server data-mesher[219]: time=2026-08-27T10:33:13.035Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWHMzUGqvUrjUDym6PeQmduKe1DyMxEgdR3R3n1uA38LwP: [/dns/client.test/tcp/7946]} {12D3KooWB335Yk2Nuh7L5BMmrmfvFY4NejMALSKAhbdfkMpycWLw: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWB335Yk2Nuh7L5BMmrmfvFY4NejMALSKAhbdfkMpycWLw192server # [6865766.982136] server data-mesher[219]: time=2026-08-27T10:33:13.035Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml193server # [6865766.983278] server data-mesher[219]: time=2026-08-27T10:33:13.036Z level=INFO msg="checking file integrity"194server # [6865766.983385] server data-mesher[219]: time=2026-08-27T10:33:13.036Z level=INFO msg="file integrity check complete"195server # [6865766.987312] server data-mesher[219]: time=2026-08-27T10:33:13.040Z level=INFO msg="libp2p host created" peer_id=12D3KooWB335Yk2Nuh7L5BMmrmfvFY4NejMALSKAhbdfkMpycWLw 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]"196server # [6865766.987360] server data-mesher[219]: time=2026-08-27T10:33:13.040Z level=INFO msg="registered HTTP route" method=GET path=/files197server # [6865766.987360] server data-mesher[219]: time=2026-08-27T10:33:13.040Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name198server # [6865766.987360] server data-mesher[219]: time=2026-08-27T10:33:13.040Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name199server # [6865766.987360] server data-mesher[219]: time=2026-08-27T10:33:13.040Z level=INFO msg="starting server"200server # [6865766.987485] server data-mesher[219]: time=2026-08-27T10:33:13.040Z level=INFO msg="waiting for DHT to populate" delay=10s201server # [6865766.987569] server data-mesher[219]: time=2026-08-27T10:33:13.040Z level=INFO msg="HTTP server listening" address=[::1]:7331202server # [6865766.987605] server data-mesher[219]: time=2026-08-27T10:33:13.040Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331203server # [6865766.992580] server data-mesher[219]: time=2026-08-27T10:33:13.045Z level=INFO msg="peer connected" peer_id=12D3KooWHMzUGqvUrjUDym6PeQmduKe1DyMxEgdR3R3n1uA38LwP remote_addr=/ip4/192.168.1.1/tcp/7946204server # [6865767.002145] server data-mesher[219]: time=2026-08-27T10:33:13.055Z level=INFO msg="peer connected" peer_id=12D3KooWHMzUGqvUrjUDym6PeQmduKe1DyMxEgdR3R3n1uA38LwP remote_addr=/ip4/192.168.1.1/tcp/49672205server # [6865767.049866] server systemd-logind[239]: New seat seat0.206server # [6865767.050065] server systemd[1]: Started User Login Management.207server # [6865767.051294] server systemd[1]: Starting linger-users.service...208server # [6865767.115452] server systemd[1]: linger-users.service: Deactivated successfully.209server # [6865767.115524] server systemd[1]: Finished linger-users.service.210client # [6865766.957729] client data-mesher[210]: time=2026-08-27T10:33:13.010Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]211client # [6865766.958805] client data-mesher[210]: time=2026-08-27T10:33:13.011Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWHMzUGqvUrjUDym6PeQmduKe1DyMxEgdR3R3n1uA38LwP: [/dns/client.test/tcp/7946]} {12D3KooWB335Yk2Nuh7L5BMmrmfvFY4NejMALSKAhbdfkMpycWLw: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWHMzUGqvUrjUDym6PeQmduKe1DyMxEgdR3R3n1uA38LwP212client # [6865766.958805] client data-mesher[210]: time=2026-08-27T10:33:13.011Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml213client # [6865766.961896] client data-mesher[210]: time=2026-08-27T10:33:13.015Z level=INFO msg="checking file integrity"214client # [6865766.962036] client data-mesher[210]: time=2026-08-27T10:33:13.015Z level=INFO msg="file integrity check complete"215client # [6865766.966852] client data-mesher[210]: time=2026-08-27T10:33:13.019Z level=INFO msg="libp2p host created" peer_id=12D3KooWHMzUGqvUrjUDym6PeQmduKe1DyMxEgdR3R3n1uA38LwP 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 # [6865766.966904] client data-mesher[210]: time=2026-08-27T10:33:13.020Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name217client # [6865766.966904] client data-mesher[210]: time=2026-08-27T10:33:13.020Z level=INFO msg="registered HTTP route" method=GET path=/files218client # [6865766.966904] client data-mesher[210]: time=2026-08-27T10:33:13.020Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name219client # [6865766.966904] client data-mesher[210]: time=2026-08-27T10:33:13.020Z level=INFO msg="starting server"220client # [6865766.967034] client data-mesher[210]: time=2026-08-27T10:33:13.020Z level=INFO msg="waiting for DHT to populate" delay=10s221client # [6865766.967118] client data-mesher[210]: time=2026-08-27T10:33:13.020Z level=INFO msg="HTTP server listening" address=[::1]:7331222client # [6865766.967163] client data-mesher[210]: time=2026-08-27T10:33:13.020Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331223client # [6865766.993564] client data-mesher[210]: time=2026-08-27T10:33:13.046Z level=INFO msg="peer connected" peer_id=12D3KooWB335Yk2Nuh7L5BMmrmfvFY4NejMALSKAhbdfkMpycWLw remote_addr=/ip4/192.168.1.2/tcp/7946224client # [6865767.001213] client data-mesher[210]: time=2026-08-27T10:33:13.054Z level=INFO msg="peer connected" peer_id=12D3KooWB335Yk2Nuh7L5BMmrmfvFY4NejMALSKAhbdfkMpycWLw remote_addr=/ip4/192.168.1.2/tcp/7946225client # [6865767.059064] client systemd-logind[230]: New seat seat0.226client # [6865767.059224] client systemd[1]: Started User Login Management.227client # [6865767.100659] client systemd[1]: Starting linger-users.service...228client # [6865767.112027] client systemd[1]: linger-users.service: Deactivated successfully.229client # [6865767.112192] client systemd[1]: Finished linger-users.service.230server # [6865767.904221] server systemd-networkd[214]: eth1: Gained IPv6LL231client # [6865768.096179] client systemd-networkd[205]: eth1: Gained IPv6LL232server: still waiting for container 'server' to reach ready state...233server # [6865776.968046] server data-mesher[219]: time=2026-08-27T10:33:23.021Z level=INFO msg="received state sync from peer" peer=12D3KooWHMzUGqvUrjUDym6PeQmduKe1DyMxEgdR3R3n1uA38LwP234client # [6865776.967178] client data-mesher[210]: time=2026-08-27T10:33:23.020Z level=INFO msg="performing state exchange with peers on join" count=1235server # [6865776.968046] server data-mesher[219]: time=2026-08-27T10:33:23.021Z level=INFO msg="merging remote state" peer=12D3KooWHMzUGqvUrjUDym6PeQmduKe1DyMxEgdR3R3n1uA38LwP236client # [6865776.967178] client data-mesher[210]: time=2026-08-27T10:33:23.020Z level=DEBUG msg="initiating state exchange" peer=12D3KooWB335Yk2Nuh7L5BMmrmfvFY4NejMALSKAhbdfkMpycWLw timeout=5s237server # [6865776.988341] server data-mesher[219]: time=2026-08-27T10:33:23.041Z level=INFO msg="performing state exchange with peers on join" count=1238client # [6865776.968288] client data-mesher[210]: time=2026-08-27T10:33:23.021Z level=INFO msg="merging remote state" peer=12D3KooWB335Yk2Nuh7L5BMmrmfvFY4NejMALSKAhbdfkMpycWLw239server # [6865776.988433] server data-mesher[219]: time=2026-08-27T10:33:23.041Z level=DEBUG msg="initiating state exchange" peer=12D3KooWHMzUGqvUrjUDym6PeQmduKe1DyMxEgdR3R3n1uA38LwP timeout=5s240client # [6865776.968288] client data-mesher[210]: time=2026-08-27T10:33:23.021Z level=INFO msg="state exchange complete" peer=12D3KooWB335Yk2Nuh7L5BMmrmfvFY4NejMALSKAhbdfkMpycWLw timeout=5s241server # [6865776.989222] server data-mesher[219]: time=2026-08-27T10:33:23.042Z level=INFO msg="merging remote state" peer=12D3KooWHMzUGqvUrjUDym6PeQmduKe1DyMxEgdR3R3n1uA38LwP242client # [6865776.968421] client data-mesher[210]: time=2026-08-27T10:33:23.021Z level=INFO msg="server started"243server # [6865776.989222] server data-mesher[219]: time=2026-08-27T10:33:23.042Z level=INFO msg="state exchange complete" peer=12D3KooWHMzUGqvUrjUDym6PeQmduKe1DyMxEgdR3R3n1uA38LwP timeout=5s244client # [6865776.968691] client systemd[1]: Started data mesher daemon.245server # [6865776.989336] server data-mesher[219]: time=2026-08-27T10:33:23.042Z level=INFO msg="server started"246client # [6865776.969201] client data-mesher[210]: time=2026-08-27T10:33:23.021Z level=INFO msg="starting expired-file sweeper" interval=1m0s247server # [6865776.989483] server data-mesher[219]: time=2026-08-27T10:33:23.042Z level=INFO msg="starting expired-file sweeper" interval=1m0s248client # [6865776.971257] client systemd[1]: Starting Unbound recursive Domain Name Server...249server # [6865776.989580] server systemd[1]: Started data mesher daemon.250client # [6865776.988902] client data-mesher[210]: time=2026-08-27T10:33:23.042Z level=INFO msg="received state sync from peer" peer=12D3KooWB335Yk2Nuh7L5BMmrmfvFY4NejMALSKAhbdfkMpycWLw251server # [6865777.004736] server systemd[1]: Starting Unbound recursive Domain Name Server...252client # [6865776.988902] client data-mesher[210]: time=2026-08-27T10:33:23.042Z level=INFO msg="merging remote state" peer=12D3KooWB335Yk2Nuh7L5BMmrmfvFY4NejMALSKAhbdfkMpycWLw253server # [6865777.511554] server unbound-pre-start[282]: Root anchor updated!254server # [6865777.526072] server unbound-pre-start[286]: setup in directory /var/lib/unbound255client # [6865777.511396] client unbound-pre-start[273]: Root anchor updated!256client # [6865777.525450] client unbound-pre-start[277]: setup in directory /var/lib/unbound257client # [6865779.078793] client unbound-pre-start[286]: Certificate request self-signature ok258client # [6865779.078793] client unbound-pre-start[286]: subject=CN=unbound-control259client # [6865779.098595] client unbound-pre-start[277]: removing artifacts260client # [6865779.100566] client unbound-pre-start[277]: Setup success. Certificates created. Enable in unbound.conf file to use261server # [6865779.234257] server unbound-pre-start[295]: Certificate request self-signature ok262server # [6865779.234257] server unbound-pre-start[295]: subject=CN=unbound-control263server # [6865779.252787] server unbound-pre-start[286]: removing artifacts264server # [6865779.254188] server unbound-pre-start[286]: Setup success. Certificates created. Enable in unbound.conf file to use265client # [6865779.630405] client unbound[291]: [291:0] notice: init module 0: validator266client # [6865779.630515] client unbound[291]: [291:0] notice: init module 1: iterator267client # [6865779.636193] client unbound[291]: [291:0] info: start of service (unbound 1.25.2).268client # [6865779.636370] client systemd[1]: Started Unbound recursive Domain Name Server.269client # [6865779.636898] client systemd[1]: Reached target Multi-User System.270client # [6865779.637161] client systemd[1]: Reached target Host and Network Name Lookups.271client # [6865779.638974] client systemd[1]: Starting Reload unbound zone configuration...272client # [6865779.693431] client unbound[291]: [291:0] info: service stopped (unbound 1.25.2).273client # [6865779.693656] client unbound[291]: [291:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting274client # [6865779.693662] client unbound[291]: [291:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0275client # [6865779.693825] client unbound-control[294]: ok276client # [6865779.695226] client unbound[291]: [291:0] notice: Restart of unbound 1.25.2.277client # [6865779.696076] client unbound[291]: [291:0] notice: init module 0: validator278client # [6865779.696132] client unbound[291]: [291:0] notice: init module 1: iterator279client # [6865779.696442] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.280client # [6865779.696655] client systemd[1]: Finished Reload unbound zone configuration.281client # [6865779.696949] client systemd[1]: Startup finished in 14.490s.282client # [6865779.700695] client unbound[291]: [291:0] info: start of service (unbound 1.25.2).283server # [6865779.794392] server unbound[300]: [300:0] notice: init module 0: validator284server # [6865779.794504] server unbound[300]: [300:0] notice: init module 1: iterator285server # [6865779.800533] server unbound[300]: [300:0] info: start of service (unbound 1.25.2).286server # [6865779.800670] server systemd[1]: Started Unbound recursive Domain Name Server.287server # [6865779.801159] server systemd[1]: Reached target Multi-User System.288server # [6865779.801418] server systemd[1]: Reached target Host and Network Name Lookups.289server # [6865779.803231] server systemd[1]: Starting Reload unbound zone configuration...290server # [6865779.868939] server unbound[300]: [300:0] info: service stopped (unbound 1.25.2).291server # [6865779.869180] server unbound[300]: [300:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting292server # [6865779.869186] server unbound[300]: [300:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0293server # [6865779.869349] server unbound-control[303]: ok294server # [6865779.870826] server unbound[300]: [300:0] notice: Restart of unbound 1.25.2.295server # [6865779.871689] server unbound[300]: [300:0] notice: init module 0: validator296server # [6865779.871748] server unbound[300]: [300:0] notice: init module 1: iterator297server # [6865779.872440] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.298server # [6865779.872717] server systemd[1]: Finished Reload unbound zone configuration.299server # [6865779.873032] server systemd[1]: Startup finished in 14.663s.300server # [6865779.876371] server unbound[300]: [300:0] info: start of service (unbound 1.25.2).301server: (finished: waiting for unit unbound.service, in 15.67 seconds)302client: waiting for unit unbound.service303client: (finished: waiting for unit unbound.service, in 0.02 seconds)304server: waiting for unit data-mesher.service305server: (finished: waiting for unit data-mesher.service, in 0.02 seconds)306server: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1307server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1, in 0.03 seconds)308server: must succeed: data-mesher file update --network-id /nix/store/b4rgbzpwb57yh8dz779rb92qkpabl4fs-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/cnames309server: (finished: must succeed: data-mesher file update --network-id /nix/store/b4rgbzpwb57yh8dz779rb92qkpabl4fs-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)310??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.311 File "/nix/store/8xlk88ia8b5yg9kfrg3skndwzgphipvr-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39312server: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test313??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.314 File "/nix/store/8xlk88ia8b5yg9kfrg3skndwzgphipvr-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39315server # [6865780.448062] server data-mesher[219]: time=2026-08-27T10:33:26.501Z level=INFO msg=http_request uri=/files/dns/cnames status=204316server # [6865780.449085] server systemd[1]: Starting Reload unbound zone configuration...317server # [6865780.477840] server unbound[300]: [300:0] info: service stopped (unbound 1.25.2).318server # [6865780.478060] server unbound-control[338]: ok319server # [6865780.478319] server unbound[300]: [300:0] info: server stats for thread 0: 5 queries, 2 answers from cache, 3 recursions, 0 prefetch, 0 rejected by ip ratelimiting320server # [6865780.478326] server unbound[300]: [300:0] info: server stats for thread 0: requestlist max 2 avg 1.33333 exceeded 0 jostled 0321server # [6865780.479940] server unbound[300]: [300:0] notice: Restart of unbound 1.25.2.322server # [6865780.480528] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.323server # [6865780.480723] server systemd[1]: Finished Reload unbound zone configuration.324server # [6865780.481517] server unbound[300]: [300:0] notice: init module 0: validator325server # [6865780.481590] server unbound[300]: [300:0] notice: init module 1: iterator326server # [6865780.487383] server unbound[300]: [300:0] info: start of service (unbound 1.25.2).327server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test, in 1.05 seconds)328(finished: run the VM test script, in 16.82 seconds)329test script finished in 16.86s330cleanup331kill NspawnMachine (pid 53)332kill NspawnMachine (pid 52)333Container client terminated by signal KILL.334Container server terminated by signal KILL.335(finished: cleanup, in 0.43 seconds)