container-test-run-dm-dns
checks.aarch64-linux.dm-dns
· build #549
· raw
1Machine state will be reset. To keep it, pass --keep-machine-state2start all VLans3(finished: start all VLans, in 0.00 seconds)45Test will time out and terminate in 3600.0 seconds6run the VM test script7additionally exposed symbols:8 client, server,9 vlan1,10 start_all, test_script, machines, machines_qemu, machines_nspawn, vlans, driver, log, os, create_machine, subtest, run_tests, join_all, retry, serial_stdout_off, serial_stdout_on, polling_condition, BaseMachine, QemuMachine, NspawnMachine, t, debug, dump_machine_ssh11start all VMs12client: systemd-nspawn running (pid 52)13server: systemd-nspawn running (pid 53)14client: Waiting for journal at /build/vm-state-client/var/log/journal...15server: Waiting for journal at /build/vm-state-server/var/log/journal...16(finished: start all VMs, in 0.00 seconds)17server: waiting for unit unbound.service18nixos-nspawn(server): TAP vde-tap1 not found; container will be isolated from VDE19nixos-nspawn(server): A common reason for this is that /dev/net is not available in the Nix sandbox. Try adding /dev/net to extra-sandbox-paths.20nixos-nspawn(client): TAP vde-tap1 not found; container will be isolated from VDE21nixos-nspawn(client): A common reason for this is that /dev/net is not available in the Nix sandbox. Try adding /dev/net to extra-sandbox-paths.22Note: in a future version of systemd-nspawn the default set of permitted socket address families will be restricted to AF_INET, AF_INET6 and AF_UNIX. Use --restrict-address-families= to configure the set of permitted socket address families, or set RestrictAddressFamilies= in a .nspawn file.23Note: in a future version of systemd-nspawn the default set of permitted socket address families will be restricted to AF_INET, AF_INET6 and AF_UNIX. Use --restrict-address-families= to configure the set of permitted socket address families, or set RestrictAddressFamilies= in a .nspawn file.24░ Spawning container server on /build/vm-state-server.25░ Spawning container client on /build/vm-state-client.26client # No journal boot entry found for the specified boot (+0).27server # No journal boot entry found for the specified boot (+0).28server # [7346580.372773] server systemd-journald[96]: Journal started29server # [7346580.372825] server systemd-journald[96]: Runtime Journal (/run/log/journal/047c49c1ff2c408da7886719c01a88f0) is 8M, max 2.5G, 2.4G free.30server # [7346580.379797] server systemd[1]: Starting Flush Journal to Persistent Storage...31server # [7346580.380551] server systemd[1]: Starting Network Name Resolution...32server # [7346580.381230] server systemd[1]: Starting Create Static Device Nodes in /dev...33server # [7346580.390664] server systemd-journald[96]: Time spent on flushing to /var/log/journal/047c49c1ff2c408da7886719c01a88f0 is 2.621ms for 5 entries.34server # [7346580.390664] server systemd-journald[96]: System Journal (/var/log/journal/047c49c1ff2c408da7886719c01a88f0) is 8M, max 4G, 3.9G free.35server # [7346580.396562] server systemd[1]: Finished Create Static Device Nodes in /dev.36server # [7346580.396791] server systemd[1]: Reached target Preparation for Local File Systems.37server # [7346580.396877] server systemd[1]: Reached target Local File Systems.38server # [7346580.397595] server systemd[1]: Listening on Boot Loader Control Service Socket.39server # [7346580.397641] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container40server # [7346580.398444] server systemd[1]: Starting Save Transient machine-id to Disk...41server # [7346580.398477] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys42server # [7346580.552354] server systemd[1]: Finished Flush Journal to Persistent Storage.43server # [7346580.552548] server systemd[1]: Finished Firewall.44server # [7346580.554221] server systemd[1]: Reached target Preparation for Network.45server # [7346580.554768] server systemd[1]: Listening on Network Management Resolve Hook Socket.46server # [7346580.556050] server systemd[1]: Starting Network Management...47server # [7346580.556894] server systemd[1]: Starting Create System Files and Directories...48server # [7346580.574227] server systemd-tmpfiles[206]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted49server # [7346580.574446] server systemd-tmpfiles[206]: fchmod() of /var/log/journal failed: Operation not permitted50server # [7346580.574591] server systemd-tmpfiles[206]: fchmod() of /var/log/journal/047c49c1ff2c408da7886719c01a88f0 failed: Operation not permitted51server # [7346580.574811] server systemd-tmpfiles[206]: fchmod() of /run/log/journal failed: Operation not permitted52server # [7346580.576894] server systemd[1]: Finished Create System Files and Directories.53server # [7346580.578521] server systemd[1]: Starting Rebuild Journal Catalog...54server # [7346580.579665] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...55server # [7346580.596262] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.56server # [7346580.602162] server systemd[1]: Finished Rebuild Journal Catalog.57server # [7346580.603874] server systemd[1]: Starting Update is Completed...58server # [7346580.617064] server systemd[1]: Finished Update is Completed.59server # [7346580.958788] server systemd-networkd[205]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted60server # [7346580.958880] server systemd-networkd[205]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted61server # [7346580.965384] server 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.62server # [7346580.965548] server 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.63server # [7346580.965709] server systemd-networkd[205]: lo: Link UP64server # [7346580.965714] server systemd-networkd[205]: lo: Gained carrier65server # [7346580.965909] server systemd-networkd[205]: eth1: Configuring with /etc/systemd/network/40-eth1.network.66server # [7346580.966316] server systemd[1]: Started Network Management.67server # [7346580.996348] server systemd-networkd[205]: eth1: Link UP68server # [7346580.996652] server systemd-networkd[205]: eth1: Gained carrier69server # [7346580.997104] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...70client # [7346580.372531] client systemd-journald[87]: Journal started71client # [7346580.372588] client systemd-journald[87]: Runtime Journal (/run/log/journal/00c87ae786e0479b81fea911d692e0c1) is 8M, max 2.5G, 2.4G free.72server # [7346581.026419] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.73server # [7346581.035000] server systemd-resolved[118]: Positive Trust Anchors:74client # [7346580.379720] client systemd[1]: Starting Flush Journal to Persistent Storage...75server # [7346581.035010] server systemd-resolved[118]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d76client # [7346580.380581] client systemd[1]: Starting Network Name Resolution...77server # [7346581.035013] server systemd-resolved[118]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b1678client # [7346580.381394] client systemd[1]: Starting Create Static Device Nodes in /dev...79server # [7346581.035048] server systemd-resolved[118]: 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 test80client # [7346580.390569] client systemd-journald[87]: Time spent on flushing to /var/log/journal/00c87ae786e0479b81fea911d692e0c1 is 2.396ms for 5 entries.81server # [7346581.056802] server systemd-resolved[118]: Using system hostname 'server'.82client # [7346580.390569] client systemd-journald[87]: System Journal (/var/log/journal/00c87ae786e0479b81fea911d692e0c1) is 8M, max 4G, 3.9G free.83server # [7346581.058191] server systemd[1]: Started Network Name Resolution.84client # [7346580.396819] client systemd[1]: Finished Create Static Device Nodes in /dev.85server # [7346581.058314] server systemd[1]: Reached target Network.86client # [7346580.397040] client systemd[1]: Reached target Preparation for Local File Systems.87server # [7346581.058436] server systemd[1]: Reached target System Initialization.88client # [7346580.397122] client systemd[1]: Reached target Local File Systems.89server # [7346581.058597] server systemd[1]: Started Watch for zone file changes.90client # [7346580.397823] client systemd[1]: Listening on Boot Loader Control Service Socket.91server # [7346581.058652] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container92client # [7346580.397864] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container93server # [7346581.058707] server systemd[1]: Started Daily Cleanup of Temporary Directories.94client # [7346580.398640] client systemd[1]: Starting Save Transient machine-id to Disk...95server # [7346581.058747] server systemd[1]: Reached target Path Units.96client # [7346580.398671] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys97server # [7346581.058815] server systemd[1]: Reached target Timer Units.98client # [7346580.499942] client systemd[1]: Finished Flush Journal to Persistent Storage.99server # [7346581.059047] server systemd[1]: Listening on D-Bus System Message Bus Socket.100client # [7346580.501442] client systemd[1]: Starting Create System Files and Directories...101server # [7346581.060801] server systemd[1]: Listening on Nix Daemon Socket.102client # [7346580.552376] client systemd[1]: Finished Firewall.103server # [7346581.061055] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.104client # [7346580.552622] client systemd[1]: Reached target Preparation for Network.105server # [7346581.061110] server systemd[1]: Reached target Socket Units.106client # [7346580.552827] client systemd[1]: Listening on Network Management Resolve Hook Socket.107server # [7346581.061201] server systemd[1]: Reached target Basic System.108client # [7346580.553864] client systemd[1]: Starting Network Management...109server # [7346581.063335] server systemd[1]: Starting data mesher daemon...110client # [7346580.565746] client systemd-tmpfiles[179]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted111server # [7346581.064572] server systemd[1]: Starting Import lastlog data into lastlog2 database...112client # [7346580.565979] client systemd-tmpfiles[179]: fchmod() of /var/log/journal failed: Operation not permitted113server # [7346581.065807] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...114client # [7346580.566142] client systemd-tmpfiles[179]: fchmod() of /var/log/journal/00c87ae786e0479b81fea911d692e0c1 failed: Operation not permitted115server # [7346581.067746] server systemd[1]: Starting D-Bus System Message Bus...116client # [7346580.566387] client systemd-tmpfiles[179]: fchmod() of /run/log/journal failed: Operation not permitted117server # [7346581.086987] server systemd[1]: Finished Import lastlog data into lastlog2 database.118client # [7346580.568272] client systemd[1]: Finished Create System Files and Directories.119server # [7346581.134359] server systemd[1]: Finished Save Transient machine-id to Disk.120client # [7346580.570323] client systemd[1]: Starting Rebuild Journal Catalog...121server # [7346581.175988] server systemd[1]: Started Name Service Cache Daemon (nsncd).122client # [7346580.571652] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...123server # [7346581.176069] server systemd[1]: Reached target User and Group Name Lookups.124client # [7346580.588145] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.125server # [7346581.176200] server nsncd[220]: Sep 02 00:06:47.229 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"126client # [7346580.592556] client systemd[1]: Finished Rebuild Journal Catalog.127server # [7346581.208594] server systemd[1]: Starting User Login Management...128client # [7346580.594222] client systemd[1]: Starting Update is Completed...129server # [7346581.209675] server systemd[1]: Starting Permit User Sessions...130client # [7346580.604692] client systemd[1]: Finished Update is Completed.131server # [7346581.219672] server systemd[1]: Finished Permit User Sessions.132client # [7346580.940187] client systemd-networkd[197]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted133server # [7346581.221229] server systemd[1]: Started Console Getty.134client # [7346580.940278] client systemd-networkd[197]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted135server # [7346581.221298] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0136client # [7346580.948105] client systemd-networkd[197]: /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.137server # [7346581.221341] server systemd[1]: Reached target Login Prompts.138client # [7346580.948273] client systemd-networkd[197]: /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.139server # [7346581.241238] server dbus-broker-launch[221]: Looking up NSS user entry for 'systemd-timesync'...140client # [7346580.948423] client systemd-networkd[197]: lo: Link UP141server # [7346581.242542] server dbus-broker-launch[221]: NSS returned no entry for 'systemd-timesync'142client # [7346580.948426] client systemd-networkd[197]: lo: Gained carrier143server # [7346581.242579] server dbus-broker-launch[221]: Invalid user-name in /nix/store/yjijkgkvvvfndi0ccc0w5g9m5k1bv440-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"144client # [7346580.948603] client systemd-networkd[197]: eth1: Configuring with /etc/systemd/network/40-eth1.network.145server # [7346581.242989] server systemd[1]: Started D-Bus System Message Bus.146client # [7346580.949010] client systemd[1]: Started Network Management.147server # [7346581.250395] server dbus-broker-launch[221]: Ready148client # [7346580.949082] client systemd-networkd[197]: eth1: Link UP149server # [7346581.367132] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.150client # [7346580.949387] client systemd-networkd[197]: eth1: Gained carrier151client # [7346580.950664] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd...152client # [7346581.007122] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd.153client # [7346581.013385] client systemd-resolved[109]: Positive Trust Anchors:154client # [7346581.013396] client systemd-resolved[109]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d155client # [7346581.013400] client systemd-resolved[109]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16156client # [7346581.013434] client systemd-resolved[109]: 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 test157client # [7346581.036032] client systemd-resolved[109]: Using system hostname 'client'.158client # [7346581.037342] client systemd[1]: Started Network Name Resolution.159client # [7346581.037447] client systemd[1]: Reached target Network.160client # [7346581.037548] client systemd[1]: Reached target System Initialization.161client # [7346581.037676] client systemd[1]: Started Watch for zone file changes.162client # [7346581.037724] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container163client # [7346581.037762] client systemd[1]: Started Daily Cleanup of Temporary Directories.164client # [7346581.037788] client systemd[1]: Reached target Path Units.165client # [7346581.037836] client systemd[1]: Reached target Timer Units.166client # [7346581.038001] client systemd[1]: Listening on D-Bus System Message Bus Socket.167client # [7346581.038176] client systemd[1]: Listening on Nix Daemon Socket.168client # [7346581.038334] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.169client # [7346581.038370] client systemd[1]: Reached target Socket Units.170client # [7346581.038425] client systemd[1]: Reached target Basic System.171client # [7346581.040140] client systemd[1]: Starting data mesher daemon...172client # [7346581.041146] client systemd[1]: Starting Import lastlog data into lastlog2 database...173client # [7346581.042217] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...174client # [7346581.043913] client systemd[1]: Starting D-Bus System Message Bus...175client # [7346581.061902] client systemd[1]: Finished Import lastlog data into lastlog2 database.176client # [7346581.134715] client systemd[1]: Finished Save Transient machine-id to Disk.177client # [7346581.149224] client nsncd[211]: Sep 02 00:06:47.202 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"178client # [7346581.149282] client systemd[1]: Started Name Service Cache Daemon (nsncd).179client # [7346581.149392] client systemd[1]: Reached target User and Group Name Lookups.180client # [7346581.151425] client systemd[1]: Starting User Login Management...181client # [7346581.152723] client systemd[1]: Starting Permit User Sessions...182client # [7346581.215912] client systemd[1]: Finished Permit User Sessions.183client # [7346581.217562] client systemd[1]: Started Console Getty.184client # [7346581.217629] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0185client # [7346581.217668] client systemd[1]: Reached target Login Prompts.186client # [7346581.243817] client dbus-broker-launch[212]: Looking up NSS user entry for 'systemd-timesync'...187client # [7346581.245009] client dbus-broker-launch[212]: NSS returned no entry for 'systemd-timesync'188client # [7346581.245009] client dbus-broker-launch[212]: Invalid user-name in /nix/store/giqgsa6vjp02ngnhasy010jgsrrlrx1x-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"189client # [7346581.245750] client systemd[1]: Started D-Bus System Message Bus.190client # [7346581.253380] client dbus-broker-launch[212]: Ready191client # [7346581.366385] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.192client # [7346581.488864] client data-mesher[209]: time=2026-09-02T00:06:47.541Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]193client # [7346581.489869] client data-mesher[209]: time=2026-09-02T00:06:47.542Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK: [/dns/client.test/tcp/7946]} {12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK194client # [7346581.489869] client data-mesher[209]: time=2026-09-02T00:06:47.543Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml195client # [7346581.610102] client data-mesher[209]: time=2026-09-02T00:06:47.663Z level=INFO msg="checking file integrity"196client # [7346581.610333] client data-mesher[209]: time=2026-09-02T00:06:47.663Z level=INFO msg="file integrity check complete"197client # [7346581.618360] client data-mesher[209]: time=2026-09-02T00:06:47.671Z level=INFO msg="libp2p host created" peer_id=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK 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]"198client # [7346581.618802] client data-mesher[209]: time=2026-09-02T00:06:47.671Z level=INFO msg="registered HTTP route" method=GET path=/files199client # [7346581.618802] client data-mesher[209]: time=2026-09-02T00:06:47.671Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name200client # [7346581.618802] client data-mesher[209]: time=2026-09-02T00:06:47.671Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name201client # [7346581.618802] client data-mesher[209]: time=2026-09-02T00:06:47.671Z level=INFO msg="starting server"202client # [7346581.619172] client data-mesher[209]: time=2026-09-02T00:06:47.672Z level=INFO msg="HTTP server listening" address=[::1]:7331203client # [7346581.619257] client data-mesher[209]: time=2026-09-02T00:06:47.672Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331204client # [7346581.619408] client data-mesher[209]: time=2026-09-02T00:06:47.672Z level=INFO msg="waiting for DHT to populate" delay=10s205client # [7346581.625071] client data-mesher[209]: time=2026-09-02T00:06:47.678Z level=INFO msg="peer connected" peer_id=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 remote_addr=/ip4/192.168.1.2/tcp/7946206client # [7346581.656638] client data-mesher[209]: time=2026-09-02T00:06:47.709Z level=INFO msg="peer connected" peer_id=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 remote_addr=/ip4/192.168.1.2/tcp/7946207client # [7346581.665121] client systemd-logind[230]: New seat seat0.208client # [7346581.665334] client systemd[1]: Started User Login Management.209client # [7346581.716742] client systemd[1]: Starting linger-users.service...210client # [7346581.730103] client systemd[1]: linger-users.service: Deactivated successfully.211client # [7346581.730225] client systemd[1]: Finished linger-users.service.212server # [7346581.504059] server data-mesher[218]: time=2026-09-02T00:06:47.557Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]213server # [7346581.505143] server data-mesher[218]: time=2026-09-02T00:06:47.558Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK: [/dns/client.test/tcp/7946]} {12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1214server # [7346581.505191] server data-mesher[218]: time=2026-09-02T00:06:47.558Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml215server # [7346581.610399] server data-mesher[218]: time=2026-09-02T00:06:47.663Z level=INFO msg="checking file integrity"216server # [7346581.610577] server data-mesher[218]: time=2026-09-02T00:06:47.663Z level=INFO msg="file integrity check complete"217server # [7346581.616292] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="libp2p host created" peer_id=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 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]"218server # [7346581.616341] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="registered HTTP route" method=GET path=/files219server # [7346581.616341] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name220server # [7346581.616414] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name221server # [7346581.616414] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="starting server"222server # [7346581.616488] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="waiting for DHT to populate" delay=10s223server # [7346581.616620] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="HTTP server listening" address=[::1]:7331224server # [7346581.616668] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331225server # [7346581.624226] server data-mesher[218]: time=2026-09-02T00:06:47.677Z level=INFO msg="peer connected" peer_id=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK remote_addr=/ip4/192.168.1.1/tcp/7946226server # [7346581.644378] server systemd-logind[239]: New seat seat0.227server # [7346581.644503] server systemd[1]: Started User Login Management.228server # [7346581.645746] server systemd[1]: Starting linger-users.service...229server # [7346581.657231] server data-mesher[218]: time=2026-09-02T00:06:47.710Z level=INFO msg="peer connected" peer_id=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK remote_addr=/ip4/192.168.1.1/tcp/43934230server # [7346581.726254] server systemd[1]: linger-users.service: Deactivated successfully.231server # [7346581.726530] server systemd[1]: Finished linger-users.service.232client # [7346582.212208] client systemd-networkd[197]: eth1: Gained IPv6LL233server # [7346582.852264] server systemd-networkd[205]: eth1: Gained IPv6LL234server: still waiting for container 'server' to reach ready state...235client # [7346591.617354] client data-mesher[209]: time=2026-09-02T00:06:57.670Z level=INFO msg="received state sync from peer" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1236client # [7346591.617354] client data-mesher[209]: time=2026-09-02T00:06:57.670Z level=INFO msg="merging remote state" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1237server # [7346591.616562] server data-mesher[218]: time=2026-09-02T00:06:57.669Z level=INFO msg="performing state exchange with peers on join" count=1238server # [7346591.616562] server data-mesher[218]: time=2026-09-02T00:06:57.669Z level=DEBUG msg="initiating state exchange" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK timeout=5s239server # [7346591.617709] server data-mesher[218]: time=2026-09-02T00:06:57.670Z level=INFO msg="merging remote state" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK240client # [7346591.621233] client data-mesher[209]: time=2026-09-02T00:06:57.674Z level=INFO msg="performing state exchange with peers on join" count=1241client # [7346591.621342] client data-mesher[209]: time=2026-09-02T00:06:57.674Z level=DEBUG msg="initiating state exchange" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 timeout=5s242client # [7346591.621840] client data-mesher[209]: time=2026-09-02T00:06:57.674Z level=INFO msg="merging remote state" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1243client # [7346591.621840] client data-mesher[209]: time=2026-09-02T00:06:57.675Z level=INFO msg="state exchange complete" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 timeout=5s244client # [7346591.621968] client data-mesher[209]: time=2026-09-02T00:06:57.675Z level=INFO msg="server started"245server # [7346591.617709] server data-mesher[218]: time=2026-09-02T00:06:57.670Z level=INFO msg="state exchange complete" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK timeout=5s246server # [7346591.617781] server data-mesher[218]: time=2026-09-02T00:06:57.670Z level=INFO msg="server started"247server # [7346591.617917] server data-mesher[218]: time=2026-09-02T00:06:57.671Z level=INFO msg="starting expired-file sweeper" interval=1m0s248client # [7346591.622023] client data-mesher[209]: time=2026-09-02T00:06:57.675Z level=INFO msg="starting expired-file sweeper" interval=1m0s249server # [7346591.618068] server systemd[1]: Started data mesher daemon.250client # [7346591.622163] client systemd[1]: Started data mesher daemon.251server # [7346591.620433] server systemd[1]: Starting Unbound recursive Domain Name Server...252client # [7346591.624450] client systemd[1]: Starting Unbound recursive Domain Name Server...253server # [7346591.621659] server data-mesher[218]: time=2026-09-02T00:06:57.674Z level=INFO msg="received state sync from peer" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK254server # [7346591.621659] server data-mesher[218]: time=2026-09-02T00:06:57.674Z level=INFO msg="merging remote state" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK255client # [7346592.527899] client unbound-pre-start[272]: Root anchor updated!256client # [7346592.542798] client unbound-pre-start[276]: setup in directory /var/lib/unbound257server # [7346592.575693] server unbound-pre-start[281]: Root anchor updated!258server # [7346592.587838] server unbound-pre-start[285]: setup in directory /var/lib/unbound259server # [7346593.500404] server unbound-pre-start[294]: Certificate request self-signature ok260server # [7346593.500404] server unbound-pre-start[294]: subject=CN=unbound-control261server # [7346593.518230] server unbound-pre-start[285]: removing artifacts262server # [7346593.519799] server unbound-pre-start[285]: Setup success. Certificates created. Enable in unbound.conf file to use263server: (finished: waiting for unit unbound.service, in 14.66 seconds)264client: waiting for unit unbound.service265server # [7346594.023620] server unbound[299]: [299:0] notice: init module 0: validator266server # [7346594.023736] server unbound[299]: [299:0] notice: init module 1: iterator267server # [7346594.029450] server unbound[299]: [299:0] info: start of service (unbound 1.26.0).268server # [7346594.029649] server systemd[1]: Started Unbound recursive Domain Name Server.269server # [7346594.030183] server systemd[1]: Reached target Multi-User System.270server # [7346594.030456] server systemd[1]: Reached target Host and Network Name Lookups.271server # [7346594.032190] server systemd[1]: Starting Reload unbound zone configuration...272server # [7346594.042917] server unbound[299]: [299:0] info: service stopped (unbound 1.26.0).273server # [7346594.043047] server unbound-control[302]: ok274server # [7346594.043266] server unbound[299]: [299:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting275server # [7346594.043271] server unbound[299]: [299:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0276server # [7346594.043923] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.277server # [7346594.044090] server systemd[1]: Finished Reload unbound zone configuration.278server # [7346594.044344] server systemd[1]: Startup finished in 14.129s.279server # [7346594.045081] server unbound[299]: [299:0] notice: Restart of unbound 1.26.0.280server # [7346594.045980] server unbound[299]: [299:0] notice: init module 0: validator281server # [7346594.046039] server unbound[299]: [299:0] notice: init module 1: iterator282server # [7346594.050589] server unbound[299]: [299:0] info: start of service (unbound 1.26.0).283client # [7346594.672538] client unbound-pre-start[285]: Certificate request self-signature ok284client # [7346594.672538] client unbound-pre-start[285]: subject=CN=unbound-control285client # [7346594.689608] client unbound-pre-start[276]: removing artifacts286client # [7346594.691058] client unbound-pre-start[276]: Setup success. Certificates created. Enable in unbound.conf file to use287client # [7346595.143582] client unbound[290]: [290:0] notice: init module 0: validator288client # [7346595.143700] client unbound[290]: [290:0] notice: init module 1: iterator289client # [7346595.149265] client unbound[290]: [290:0] info: start of service (unbound 1.26.0).290client # [7346595.149397] client systemd[1]: Started Unbound recursive Domain Name Server.291client # [7346595.149731] client systemd[1]: Reached target Multi-User System.292client # [7346595.149902] client systemd[1]: Reached target Host and Network Name Lookups.293client # [7346595.151104] client systemd[1]: Starting Reload unbound zone configuration...294client # [7346595.245118] client unbound[290]: [290:0] info: service stopped (unbound 1.26.0).295client # [7346595.245453] client unbound-control[293]: ok296client # [7346595.245453] 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 ratelimiting297client # [7346595.245459] client unbound[290]: [290:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0298client # [7346595.246579] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.299client # [7346595.246746] client systemd[1]: Finished Reload unbound zone configuration.300client # [7346595.247064] client systemd[1]: Startup finished in 15.336s.301client # [7346595.247161] client unbound[290]: [290:0] notice: Restart of unbound 1.26.0.302client # [7346595.248043] client unbound[290]: [290:0] notice: init module 0: validator303client # [7346595.248104] client unbound[290]: [290:0] notice: init module 1: iterator304client # [7346595.252621] client unbound[290]: [290:0] info: start of service (unbound 1.26.0).305client: (finished: waiting for unit unbound.service, in 1.65 seconds)306server: waiting for unit data-mesher.service307server: (finished: waiting for unit data-mesher.service, in 0.01 seconds)308server: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1309server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1, in 0.02 seconds)310server: must succeed: data-mesher file update --network-id /nix/store/6bp1ql9d8rnj8smbfd7nqnr4fs508w37-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/cnames311server: (finished: must succeed: data-mesher file update --network-id /nix/store/6bp1ql9d8rnj8smbfd7nqnr4fs508w37-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.26 seconds)312??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.313 File "/nix/store/pg5lbaicpvf34wrdmfh8riwp8avk7lk6-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39314server: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test315??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.316 File "/nix/store/pg5lbaicpvf34wrdmfh8riwp8avk7lk6-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39317server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test, in 0.03 seconds)318(finished: run the VM test script, in 16.64 seconds)319server # [7346595.781012] server systemd[1]: Starting Reload unbound zone configuration...320server # [7346595.793037] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.321server # [7346595.792531] server unbound[299]: [299:0] info: service stopped (unbound 1.26.0).322server # [7346595.793228] server systemd[1]: Finished Reload unbound zone configuration.323server # [7346595.793066] server unbound[299]: [299:0] info: server stats for thread 0: 6 queries, 1 answers from cache, 5 recursions, 0 prefetch, 0 rejected by ip ratelimiting324server # [7346595.807148] server unbound-control[337]: ok325server # [7346595.793074] server unbound[299]: [299:0] info: server stats for thread 0: requestlist max 2 avg 1.6 exceeded 0 jostled 0326server # [7346595.794859] server unbound[299]: [299:0] notice: Restart of unbound 1.26.0.327server # [7346595.796610] server unbound[299]: [299:0] notice: init module 0: validator328server # [7346595.796701] server unbound[299]: [299:0] notice: init module 1: iterator329server # [7346595.804385] server unbound[299]: [299:0] info: start of service (unbound 1.26.0).330server # [7346596.014899] server data-mesher[218]: time=2026-09-02T00:07:02.068Z level=INFO msg=http_request uri=/files/dns/cnames status=204331server # [7346596.617959] server data-mesher[218]: time=2026-09-02T00:07:02.671Z level=DEBUG msg="attempting push/pull" peer_count=1332server # [7346596.618193] server data-mesher[218]: time=2026-09-02T00:07:02.671Z level=DEBUG msg="initiating state exchange" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK timeout=5s333server # [7346596.620029] server data-mesher[218]: time=2026-09-02T00:07:02.673Z level=INFO msg="merging remote state" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK334server # [7346596.620029] server data-mesher[218]: time=2026-09-02T00:07:02.673Z level=INFO msg="state exchange complete" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK timeout=5s335server # [7346596.620229] server data-mesher[218]: time=2026-09-02T00:07:02.673Z level=DEBUG msg="push/pull successful" interval=5s336server # [7346596.620555] server data-mesher[218]: time=2026-09-02T00:07:02.673Z level=INFO msg="received file request" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK network="NNiAQspFX8fHGaev/7r86puAuL/Dx4c50ZIOCfqA5m4=" name=dns/cnames337server # [7346596.621761] server data-mesher[218]: time=2026-09-02T00:07:02.674Z level=INFO msg="file transfer complete" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK network="NNiAQspFX8fHGaev/7r86puAuL/Dx4c50ZIOCfqA5m4=" name=dns/cnames338server # [7346596.623435] server data-mesher[218]: time=2026-09-02T00:07:02.676Z level=INFO msg="received state sync from peer" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK339server # [7346596.623435] server data-mesher[218]: time=2026-09-02T00:07:02.676Z level=INFO msg="merging remote state" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK340client # [7346596.619851] client data-mesher[209]: time=2026-09-02T00:07:02.672Z level=INFO msg="received state sync from peer" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1341client # [7346596.619851] client data-mesher[209]: time=2026-09-02T00:07:02.672Z level=INFO msg="merging remote state" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1342client # [7346596.619851] client data-mesher[209]: time=2026-09-02T00:07:02.672Z level=DEBUG msg="new file detected" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 name=dns/cnames name=dns/cnames343client # [7346596.619851] client data-mesher[209]: time=2026-09-02T00:07:02.673Z level=INFO msg="scheduling file download" name=dns/cnames344client # [7346596.620713] client data-mesher[209]: time=2026-09-02T00:07:02.673Z level=INFO msg="downloading file" name=dns/cnames signed_at="2026-09-02 00:07:01.829 +0000 UTC" signed_by="eA59Fb3MpXgWfNOasjZK0yOoio7t9Kgwv4qZRnipPbU=" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1345client # [7346596.622650] client data-mesher[209]: time=2026-09-02T00:07:02.675Z level=DEBUG msg="attempting push/pull" peer_count=1346client # [7346596.622755] client data-mesher[209]: time=2026-09-02T00:07:02.675Z level=DEBUG msg="initiating state exchange" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 timeout=5s347client # [7346596.623796] client data-mesher[209]: time=2026-09-02T00:07:02.676Z level=INFO msg="merging remote state" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1348client # [7346596.623872] client data-mesher[209]: time=2026-09-02T00:07:02.676Z level=DEBUG msg="new file detected" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 name=dns/cnames name=dns/cnames349client # [7346596.623872] client data-mesher[209]: time=2026-09-02T00:07:02.676Z level=INFO msg="state exchange complete" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 timeout=5s350client # [7346596.623872] client data-mesher[209]: time=2026-09-02T00:07:02.677Z level=DEBUG msg="push/pull successful" interval=5s351client # [7346596.627381] client systemd[1]: Starting Reload unbound zone configuration...352client # [7346596.647688] client data-mesher[209]: time=2026-09-02T00:07:02.700Z level=INFO msg="download complete" name=dns/cnames signed_at="2026-09-02 00:07:01.829 +0000 UTC" signed_by="eA59Fb3MpXgWfNOasjZK0yOoio7t9Kgwv4qZRnipPbU=" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 written=true elapsed=27.729936ms353client # [7346596.849086] client unbound[290]: [290:0] info: service stopped (unbound 1.26.0).354client # [7346596.849582] client unbound-control[300]: ok355client # [7346596.849722] client unbound[290]: [290:0] info: server stats for thread 0: 5 queries, 0 answers from cache, 5 recursions, 0 prefetch, 0 rejected by ip ratelimiting356client # [7346596.849732] client unbound[290]: [290:0] info: server stats for thread 0: requestlist max 2 avg 1.6 exceeded 0 jostled 0357client # [7346596.851886] client unbound[290]: [290:0] notice: Restart of unbound 1.26.0.358client # [7346596.852732] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.359client # [7346596.852995] client systemd[1]: Finished Reload unbound zone configuration.360client # [7346596.856227] client unbound[290]: [290:0] notice: init module 0: validator361client # [7346596.856345] client unbound[290]: [290:0] notice: init module 1: iterator362client # [7346596.867329] client unbound[290]: [290:0] info: start of service (unbound 1.26.0).363test script finished in 18.23s364cleanup365kill NspawnMachine (pid 52)366kill NspawnMachine (pid 53)367Container client terminated by signal KILL.368(finished: cleanup, in 0.33 seconds)369Container server terminated by signal KILL.