container-test-run-dm-dns
checks.aarch64-linux.dm-dns
· build #964
· raw
1build01: building hfnr5c5dcsxbm3vm00jw4c9r6s49czdq-container-test-run-dm-dns.drv2Machine state will be reset. To keep it, pass --keep-machine-state3start all VLans4(finished: start all VLans, in 0.00 seconds)56Test will time out and terminate in 3600.0 seconds7run the VM test script8additionally exposed symbols:9 client, server,10 vlan1,11 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_ssh12start all VMs13client: systemd-nspawn running (pid 52)14client: Waiting for journal at /build/vm-state-client/var/log/journal...15server: systemd-nspawn running (pid 55)16server: Waiting for journal at /build/vm-state-server/var/log/journal...17(finished: start all VMs, in 0.01 seconds)18server: waiting for unit unbound.service19nixos-nspawn(client): TAP vde-tap1 not found; container will be isolated from VDE20nixos-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.21nixos-nspawn(server): TAP vde-tap1 not found; container will be isolated from VDE22nixos-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.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.25Note: 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.26░ Spawning container server on /build/vm-state-server.27client # No journal files were found.28client # No journal boot entry found for the specified boot (+0).29server # No journal files were found.30server # No journal boot entry found for the specified boot (+0).31client # [361801.461800] client systemd-journald[89]: Journal started32client # [361801.461860] client systemd-journald[89]: Runtime Journal (/run/log/journal/a2a4a3c848bd423089cea1e70e37a1b9) is 8M, max 2.5G, 2.4G free.33client # [361801.476233] client systemd[1]: Finished Apply Kernel Variables.34client # [361801.491229] client systemd[1]: Finished Create Static Device Nodes in /dev gracefully.35client # [361801.506980] client systemd[1]: Starting Flush Journal to Persistent Storage...36client # [361801.508012] client systemd[1]: Starting Network Name Resolution...37client # [361801.508637] client systemd[1]: Starting Create Static Device Nodes in /dev...38client # [361801.516571] client systemd-journald[89]: Time spent on flushing to /var/log/journal/a2a4a3c848bd423089cea1e70e37a1b9 is 2.165ms for 7 entries.39client # [361801.516571] client systemd-journald[89]: System Journal (/var/log/journal/a2a4a3c848bd423089cea1e70e37a1b9) is 8M, max 4G, 3.9G free.40client # [361801.532791] client systemd[1]: Finished Create Static Device Nodes in /dev.41client # [361801.533409] client systemd[1]: Reached target Preparation for Local File Systems.42client # [361801.533527] client systemd[1]: Reached target Local File Systems.43client # [361801.534389] client systemd[1]: Listening on Boot Loader Control Service Socket.44client # [361801.534437] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container45client # [361801.535295] client systemd[1]: Starting Save Transient machine-id to Disk...46client # [361801.535335] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys47client # [361801.539527] client systemd[1]: Finished Flush Journal to Persistent Storage.48client # [361801.540772] client systemd[1]: Starting Create System Files and Directories...49client # [361801.557477] client systemd-tmpfiles[153]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted50client # [361801.557687] client systemd-tmpfiles[153]: fchmod() of /var/log/journal failed: Operation not permitted51client # [361801.557836] client systemd-tmpfiles[153]: fchmod() of /var/log/journal/a2a4a3c848bd423089cea1e70e37a1b9 failed: Operation not permitted52client # [361801.558057] client systemd-tmpfiles[153]: fchmod() of /run/log/journal failed: Operation not permitted53client # [361801.559473] client systemd[1]: Finished Create System Files and Directories.54client # [361801.560554] client systemd[1]: Starting Rebuild Journal Catalog...55client # [361801.561449] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...56client # [361801.575781] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.57client # [361801.583197] client systemd[1]: Finished Rebuild Journal Catalog.58client # [361801.584233] client systemd[1]: Starting Update is Completed...59client # [361801.594562] client systemd[1]: Finished Update is Completed.60client # [361801.633781] client systemd[1]: Finished Firewall.61client # [361801.633928] client systemd[1]: Reached target Preparation for Network.62client # [361801.634141] client systemd[1]: Listening on Network Management Resolve Hook Socket.63client # [361801.635180] client systemd[1]: Starting Network Management...64client # [361802.283910] client systemd-networkd[206]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted65client # [361802.284022] client systemd-networkd[206]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted66client # [361802.293570] client systemd-networkd[206]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.67client # [361802.293741] client systemd-networkd[206]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.68client # [361802.293913] client systemd-networkd[206]: lo: Link UP69client # [361802.293918] client systemd-networkd[206]: lo: Gained carrier70client # [361802.294121] client systemd-networkd[206]: eth1: Configuring with /etc/systemd/network/40-eth1.network.71client # [361802.294553] client systemd[1]: Started Network Management.72client # [361802.294573] client systemd-networkd[206]: eth1: Link UP73client # [361802.294813] client systemd-networkd[206]: eth1: Gained carrier74client # [361802.296363] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd...75client # [361802.354021] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd.76server # [361801.469628] server systemd-journald[98]: Journal started77server # [361801.469684] server systemd-journald[98]: Runtime Journal (/run/log/journal/c024e2a22ddd475096c92da8e9366666) is 8M, max 2.5G, 2.4G free.78server # [361801.474913] server systemd[1]: Finished Apply Kernel Variables.79server # [361801.486462] server systemd[1]: Finished Create Static Device Nodes in /dev gracefully.80server # [361801.499508] server systemd[1]: Starting Flush Journal to Persistent Storage...81server # [361801.500318] server systemd[1]: Starting Network Name Resolution...82server # [361801.500963] server systemd[1]: Starting Create Static Device Nodes in /dev...83server # [361801.509843] server systemd-journald[98]: Time spent on flushing to /var/log/journal/c024e2a22ddd475096c92da8e9366666 is 1.194ms for 7 entries.84server # [361801.509843] server systemd-journald[98]: System Journal (/var/log/journal/c024e2a22ddd475096c92da8e9366666) is 8M, max 4G, 3.9G free.85server # [361801.524816] server systemd[1]: Finished Create Static Device Nodes in /dev.86server # [361801.525423] server systemd[1]: Reached target Preparation for Local File Systems.87server # [361801.525538] server systemd[1]: Reached target Local File Systems.88server # [361801.526391] server systemd[1]: Listening on Boot Loader Control Service Socket.89server # [361801.526437] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container90server # [361801.527450] server systemd[1]: Starting Save Transient machine-id to Disk...91server # [361801.527489] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys92server # [361801.538714] server systemd[1]: Finished Flush Journal to Persistent Storage.93server # [361801.540356] server systemd[1]: Starting Create System Files and Directories...94server # [361801.557914] server systemd-tmpfiles[158]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted95server # [361801.558127] server systemd-tmpfiles[158]: fchmod() of /var/log/journal failed: Operation not permitted96server # [361801.558278] server systemd-tmpfiles[158]: fchmod() of /var/log/journal/c024e2a22ddd475096c92da8e9366666 failed: Operation not permitted97server # [361801.558502] server systemd-tmpfiles[158]: fchmod() of /run/log/journal failed: Operation not permitted98server # [361801.559829] server systemd[1]: Finished Create System Files and Directories.99server # [361801.561051] server systemd[1]: Starting Rebuild Journal Catalog...100server # [361801.561857] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...101server # [361801.576545] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.102server # [361801.584446] server systemd[1]: Finished Rebuild Journal Catalog.103server # [361801.585595] server systemd[1]: Starting Update is Completed...104server # [361801.595532] server systemd[1]: Finished Update is Completed.105server # [361801.644528] server systemd[1]: Finished Firewall.106server # [361801.644676] server systemd[1]: Reached target Preparation for Network.107server # [361801.644891] server systemd[1]: Listening on Network Management Resolve Hook Socket.108server # [361801.645858] server systemd[1]: Starting Network Management...109server # [361802.285725] server systemd-networkd[215]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted110server # [361802.285818] server systemd-networkd[215]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted111server # [361802.295058] server systemd-networkd[215]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.112server # [361802.295226] server systemd-networkd[215]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.113server # [361802.295359] server systemd-networkd[215]: lo: Link UP114server # [361802.295363] server systemd-networkd[215]: lo: Gained carrier115server # [361802.295530] server systemd-networkd[215]: eth1: Configuring with /etc/systemd/network/40-eth1.network.116server # [361802.295898] server systemd[1]: Started Network Management.117server # [361802.295975] server systemd-networkd[215]: eth1: Link UP118server # [361802.296394] server systemd-networkd[215]: eth1: Gained carrier119server # [361802.297169] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...120server # [361802.354460] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.121client # [361802.609178] client systemd-resolved[130]: Positive Trust Anchors:122client # [361802.609188] client systemd-resolved[130]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d123client # [361802.609192] client systemd-resolved[130]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16124client # [361802.609226] client systemd-resolved[130]: 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 test125client # [361802.629981] client systemd-resolved[130]: Using system hostname 'client'.126client # [361802.631321] client systemd[1]: Started Network Name Resolution.127client # [361802.631449] client systemd[1]: Reached target Network.128client # [361802.631576] client systemd[1]: Reached target System Initialization.129client # [361802.631744] client systemd[1]: Started Watch for zone file changes.130client # [361802.631799] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container131client # [361802.631845] client systemd[1]: Started Daily Cleanup of Temporary Directories.132client # [361802.631886] client systemd[1]: Reached target Path Units.133client # [361802.631956] client systemd[1]: Reached target Timer Units.134client # [361802.632222] client systemd[1]: Listening on D-Bus System Message Bus Socket.135client # [361802.632435] client systemd[1]: Listening on Nix Daemon Socket.136client # [361802.632651] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.137client # [361802.632698] client systemd[1]: Reached target Socket Units.138client # [361802.632771] client systemd[1]: Reached target Basic System.139client # [361802.635418] client systemd[1]: Starting data mesher daemon...140client # [361802.636931] client systemd[1]: Starting Import lastlog data into lastlog2 database...141client # [361802.638376] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...142client # [361802.676684] client systemd[1]: Starting D-Bus System Message Bus...143client # [361802.694864] client systemd[1]: Finished Import lastlog data into lastlog2 database.144client # [361802.883258] client systemd[1]: Started Name Service Cache Daemon (nsncd).145client # [361802.883368] client systemd[1]: Reached target User and Group Name Lookups.146server # [361802.596945] server systemd-resolved[131]: Positive Trust Anchors:147server # [361802.596958] server systemd-resolved[131]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d148server # [361802.596961] server systemd-resolved[131]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16149server # [361802.596996] server systemd-resolved[131]: 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 test150server # [361802.629274] server systemd-resolved[131]: Using system hostname 'server'.151server # [361802.630680] server systemd[1]: Started Network Name Resolution.152server # [361802.630814] server systemd[1]: Reached target Network.153server # [361802.630936] server systemd[1]: Reached target System Initialization.154server # [361802.631093] server systemd[1]: Started Watch for zone file changes.155server # [361802.631147] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container156server # [361802.631200] server systemd[1]: Started Daily Cleanup of Temporary Directories.157server # [361802.631239] server systemd[1]: Reached target Path Units.158server # [361802.631309] server systemd[1]: Reached target Timer Units.159server # [361802.631529] server systemd[1]: Listening on D-Bus System Message Bus Socket.160server # [361802.631740] server systemd[1]: Listening on Nix Daemon Socket.161server # [361802.631971] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.162server # [361802.632051] server systemd[1]: Reached target Socket Units.163server # [361802.632139] server systemd[1]: Reached target Basic System.164server # [361802.634519] server systemd[1]: Starting data mesher daemon...165server # [361802.635940] server systemd[1]: Starting Import lastlog data into lastlog2 database...166server # [361802.637422] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...167server # [361802.639632] server systemd[1]: Starting D-Bus System Message Bus...168server # [361802.695180] server systemd[1]: Finished Import lastlog data into lastlog2 database.169server # [361802.892496] server systemd[1]: Started Name Service Cache Daemon (nsncd).170server # [361802.892562] server systemd[1]: Reached target User and Group Name Lookups.171server # [361802.898906] server nsncd[222]: Oct 13 15:35:05.856 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"172server # [361802.928879] server systemd[1]: Starting User Login Management...173server # [361802.930167] server systemd[1]: Starting Permit User Sessions...174server # [361802.943353] server systemd[1]: Finished Permit User Sessions.175server # [361802.945324] server systemd[1]: Started Console Getty.176server # [361802.945410] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0177server # [361802.945457] server systemd[1]: Reached target Login Prompts.178server # [361803.035496] server dbus-broker-launch[223]: Looking up NSS user entry for 'systemd-timesync'...179server # [361803.037201] server dbus-broker-launch[223]: NSS returned no entry for 'systemd-timesync'180server # [361803.037201] server dbus-broker-launch[223]: Invalid user-name in /nix/store/n242z8x42xlxbmldm7w0y6hdxcf3r229-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"181server # [361803.038092] server systemd[1]: Started D-Bus System Message Bus.182server # [361803.046385] server dbus-broker-launch[223]: Ready183client # [361802.886611] client systemd[1]: Starting User Login Management...184client # [361802.888590] client systemd[1]: Starting Permit User Sessions...185client # [361802.893877] client nsncd[213]: Oct 13 15:35:05.851 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"186client # [361802.936465] client systemd[1]: Finished Permit User Sessions.187client # [361802.937822] client systemd[1]: Started Console Getty.188client # [361802.937873] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0189client # [361802.937900] client systemd[1]: Reached target Login Prompts.190client # [361803.037849] client dbus-broker-launch[214]: Looking up NSS user entry for 'systemd-timesync'...191client # [361803.039580] client dbus-broker-launch[214]: NSS returned no entry for 'systemd-timesync'192client # [361803.039580] client dbus-broker-launch[214]: Invalid user-name in /nix/store/l1vr068fvilnvpjp61z0nd2hrndnidbs-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"193client # [361803.040355] client systemd[1]: Started D-Bus System Message Bus.194client # [361803.048252] client dbus-broker-launch[214]: Ready195client # [361803.469123] client data-mesher[211]: time=2026-10-13T15:35:06.426Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]196client # [361803.470233] client data-mesher[211]: time=2026-10-13T15:35:06.427Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt: [/dns/client.test/tcp/7946]} {12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt197client # [361803.470281] client data-mesher[211]: time=2026-10-13T15:35:06.427Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml198client # [361803.474203] client data-mesher[211]: time=2026-10-13T15:35:06.431Z level=INFO msg="checking file integrity"199client # [361803.474370] client data-mesher[211]: time=2026-10-13T15:35:06.431Z level=INFO msg="file integrity check complete"200client # [361803.479040] client data-mesher[211]: time=2026-10-13T15:35:06.436Z level=INFO msg="libp2p host created" peer_id=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt 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]"201client # [361803.479106] client data-mesher[211]: time=2026-10-13T15:35:06.436Z level=INFO msg="registered HTTP route" method=GET path=/files202client # [361803.479106] client data-mesher[211]: time=2026-10-13T15:35:06.436Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name203client # [361803.479106] client data-mesher[211]: time=2026-10-13T15:35:06.436Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name204client # [361803.479106] client data-mesher[211]: time=2026-10-13T15:35:06.436Z level=INFO msg="starting server"205client # [361803.479242] client data-mesher[211]: time=2026-10-13T15:35:06.436Z level=INFO msg="waiting for DHT to populate" delay=10s206client # [361803.479288] client data-mesher[211]: time=2026-10-13T15:35:06.436Z level=INFO msg="HTTP server listening" address=[::1]:7331207client # [361803.479333] client data-mesher[211]: time=2026-10-13T15:35:06.436Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331208client # [361803.484881] client data-mesher[211]: time=2026-10-13T15:35:06.442Z level=INFO msg="peer connected" peer_id=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7 remote_addr=/ip4/192.168.1.2/tcp/7946209client # [361803.513872] client data-mesher[211]: time=2026-10-13T15:35:06.471Z level=INFO msg="peer connected" peer_id=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7 remote_addr=/ip4/192.168.1.2/tcp/7946210client # [361803.673695] client systemd-logind[226]: New seat seat0.211client # [361803.674079] client systemd[1]: Started User Login Management.212client # [361803.675736] client systemd[1]: Starting linger-users.service...213server # [361803.464844] server data-mesher[220]: time=2026-10-13T15:35:06.422Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]214server # [361803.468890] server data-mesher[220]: time=2026-10-13T15:35:06.426Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt: [/dns/client.test/tcp/7946]} {12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7215server # [361803.468890] server data-mesher[220]: time=2026-10-13T15:35:06.426Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml216server # [361803.474194] server data-mesher[220]: time=2026-10-13T15:35:06.431Z level=INFO msg="checking file integrity"217server # [361803.474449] server data-mesher[220]: time=2026-10-13T15:35:06.432Z level=INFO msg="file integrity check complete"218server # [361803.478742] server data-mesher[220]: time=2026-10-13T15:35:06.436Z level=INFO msg="libp2p host created" peer_id=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7 addresses="[/ip4/127.0.0.1/tcp/7946 /ip4/192.168.1.2/tcp/7946 /ip6/::1/tcp/7946 /ip6/2001:db8:1::2/tcp/7946]"219server # [361803.478788] server data-mesher[220]: time=2026-10-13T15:35:06.436Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name220server # [361803.478788] server data-mesher[220]: time=2026-10-13T15:35:06.436Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name221server # [361803.478788] server data-mesher[220]: time=2026-10-13T15:35:06.436Z level=INFO msg="registered HTTP route" method=GET path=/files222server # [361803.478788] server data-mesher[220]: time=2026-10-13T15:35:06.436Z level=INFO msg="starting server"223server # [361803.478968] server data-mesher[220]: time=2026-10-13T15:35:06.436Z level=INFO msg="waiting for DHT to populate" delay=10s224server # [361803.479006] server data-mesher[220]: time=2026-10-13T15:35:06.436Z level=INFO msg="HTTP server listening" address=[::1]:7331225server # [361803.479006] server data-mesher[220]: time=2026-10-13T15:35:06.436Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331226server # [361803.484222] server data-mesher[220]: time=2026-10-13T15:35:06.441Z level=INFO msg="peer connected" peer_id=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt remote_addr=/ip4/192.168.1.1/tcp/7946227server # [361803.514515] server data-mesher[220]: time=2026-10-13T15:35:06.472Z level=INFO msg="peer connected" peer_id=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt remote_addr=/ip4/192.168.1.1/tcp/46332228server # [361803.701613] server systemd-logind[235]: New seat seat0.229server # [361803.701804] server systemd[1]: Started User Login Management.230server # [361803.720551] server systemd[1]: Starting linger-users.service...231server # [361803.736173] server systemd[1]: linger-users.service: Deactivated successfully.232server # [361803.736269] server systemd[1]: Finished linger-users.service.233server # [361803.840141] server systemd-networkd[215]: eth1: Gained IPv6LL234client # [361803.731544] client systemd[1]: linger-users.service: Deactivated successfully.235client # [361803.731775] client systemd[1]: Finished linger-users.service.236client # [361803.868131] client systemd-networkd[206]: eth1: Gained IPv6LL237server # [361804.334928] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.238server # [361804.335994] server systemd[1]: Finished Save Transient machine-id to Disk.239client # [361804.352466] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.240client # [361804.354308] client systemd[1]: Finished Save Transient machine-id to Disk.241server: still waiting for container 'server' to reach ready state...242server # [361813.479300] server data-mesher[220]: time=2026-10-13T15:35:16.436Z level=INFO msg="performing state exchange with peers on join" count=1243server # [361813.480052] server data-mesher[220]: time=2026-10-13T15:35:16.436Z level=DEBUG msg="initiating state exchange" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt timeout=5s244server # [361813.480455] server data-mesher[220]: time=2026-10-13T15:35:16.438Z level=INFO msg="merging remote state" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt245server # [361813.480455] server data-mesher[220]: time=2026-10-13T15:35:16.438Z level=INFO msg="state exchange complete" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt timeout=5s246server # [361813.480581] server data-mesher[220]: time=2026-10-13T15:35:16.438Z level=INFO msg="received state sync from peer" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt247server # [361813.480581] server data-mesher[220]: time=2026-10-13T15:35:16.438Z level=INFO msg="merging remote state" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt248server # [361813.480681] server data-mesher[220]: time=2026-10-13T15:35:16.438Z level=INFO msg="server started"249server # [361813.480886] server data-mesher[220]: time=2026-10-13T15:35:16.438Z level=INFO msg="starting expired-file sweeper" interval=1m0s250server # [361813.480942] server systemd[1]: Started data mesher daemon.251server # [361813.483581] server systemd[1]: Starting Unbound recursive Domain Name Server...252client # [361813.479691] client data-mesher[211]: time=2026-10-13T15:35:16.437Z level=INFO msg="performing state exchange with peers on join" count=1253client # [361813.479691] client data-mesher[211]: time=2026-10-13T15:35:16.437Z level=DEBUG msg="initiating state exchange" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7 timeout=5s254client # [361813.480494] client data-mesher[211]: time=2026-10-13T15:35:16.437Z level=INFO msg="received state sync from peer" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7255client # [361813.480494] client data-mesher[211]: time=2026-10-13T15:35:16.437Z level=INFO msg="merging remote state" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7256client # [361813.480695] client data-mesher[211]: time=2026-10-13T15:35:16.438Z level=INFO msg="merging remote state" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7257client # [361813.480695] client data-mesher[211]: time=2026-10-13T15:35:16.438Z level=INFO msg="state exchange complete" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7 timeout=5s258client # [361813.480878] client data-mesher[211]: time=2026-10-13T15:35:16.438Z level=INFO msg="server started"259client # [361813.480878] client data-mesher[211]: time=2026-10-13T15:35:16.438Z level=INFO msg="starting expired-file sweeper" interval=1m0s260client # [361813.481017] client systemd[1]: Started data mesher daemon.261client # [361813.483692] client systemd[1]: Starting Unbound recursive Domain Name Server...262server # [361814.396434] server unbound-pre-start[284]: Root anchor updated!263server # [361814.412461] server unbound-pre-start[288]: setup in directory /var/lib/unbound264client # [361814.397193] client unbound-pre-start[274]: Root anchor updated!265client # [361814.412325] client unbound-pre-start[278]: setup in directory /var/lib/unbound266client # [361815.693208] client unbound-pre-start[287]: Certificate request self-signature ok267client # [361815.693208] client unbound-pre-start[287]: subject=CN=unbound-control268client # [361815.713940] client unbound-pre-start[278]: removing artifacts269client # [361815.715902] client unbound-pre-start[278]: Setup success. Certificates created. Enable in unbound.conf file to use270server # [361816.082145] server unbound-pre-start[297]: Certificate request self-signature ok271server # [361816.082145] server unbound-pre-start[297]: subject=CN=unbound-control272server # [361816.102038] server unbound-pre-start[288]: removing artifacts273server # [361816.103595] server unbound-pre-start[288]: Setup success. Certificates created. Enable in unbound.conf file to use274client # [361816.621761] client unbound[291]: [291:0] notice: init module 0: validator275client # [361816.621838] client unbound[291]: [291:0] notice: init module 1: iterator276client # [361816.626195] client unbound[291]: [291:0] info: start of service (unbound 1.26.1).277client # [361816.626297] client systemd[1]: Started Unbound recursive Domain Name Server.278client # [361816.626814] client systemd[1]: Reached target Multi-User System.279client # [361816.627097] client systemd[1]: Reached target Host and Network Name Lookups.280client # [361816.628960] client systemd[1]: Starting Reload unbound zone configuration...281client # [361816.673132] client unbound[291]: [291:0] info: service stopped (unbound 1.26.1).282client # [361816.673469] client unbound-control[295]: ok283client # [361816.673516] 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 ratelimiting284client # [361816.673522] client unbound[291]: [291:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0285client # [361816.674586] client unbound[291]: [291:0] notice: Restart of unbound 1.26.1.286client # [361816.674653] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.287client # [361816.674942] client systemd[1]: Finished Reload unbound zone configuration.288client # [361816.675296] client systemd[1]: Startup finished in 15.669s.289client # [361816.675318] client unbound[291]: [291:0] notice: init module 0: validator290client # [361816.675369] client unbound[291]: [291:0] notice: init module 1: iterator291client # [361816.679200] client unbound[291]: [291:0] info: start of service (unbound 1.26.1).292server: (finished: waiting for unit unbound.service, in 16.68 seconds)293client: waiting for unit unbound.service294client: (finished: waiting for unit unbound.service, in 0.02 seconds)295server: waiting for unit data-mesher.service296server: (finished: waiting for unit data-mesher.service, in 0.02 seconds)297server: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1298server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1, in 0.04 seconds)299server: must succeed: data-mesher file update --network-id /nix/store/bwl6q2vfh9cxkqnapgngamska8vhkjwi-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/cnames300server # [361816.961974] server unbound[302]: [302:0] notice: init module 0: validator301server # [361816.962050] server unbound[302]: [302:0] notice: init module 1: iterator302server # [361816.966197] server unbound[302]: [302:0] info: start of service (unbound 1.26.1).303server # [361816.966348] server systemd[1]: Started Unbound recursive Domain Name Server.304server # [361816.966852] server systemd[1]: Reached target Multi-User System.305server # [361816.967121] server systemd[1]: Reached target Host and Network Name Lookups.306server # [361816.969217] server systemd[1]: Starting Reload unbound zone configuration...307server # [361817.025360] server unbound[302]: [302:0] info: service stopped (unbound 1.26.1).308server # [361817.025706] server unbound-control[305]: ok309server # [361817.025743] 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 ratelimiting310server # [361817.025747] server unbound[302]: [302:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0311server # [361817.026761] server unbound[302]: [302:0] notice: Restart of unbound 1.26.1.312server # [361817.027480] server unbound[302]: [302:0] notice: init module 0: validator313server # [361817.027534] server unbound[302]: [302:0] notice: init module 1: iterator314server # [361817.027888] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.315server # [361817.028173] server systemd[1]: Finished Reload unbound zone configuration.316server # [361817.028550] server systemd[1]: Startup finished in 15.942s.317server # [361817.031418] server unbound[302]: [302:0] info: start of service (unbound 1.26.1).318server # [361817.201598] server systemd[1]: Starting Reload unbound zone configuration...319server: (finished: must succeed: data-mesher file update --network-id /nix/store/bwl6q2vfh9cxkqnapgngamska8vhkjwi-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.09 seconds)320??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.321 File "/nix/store/x4i03lhka9aiwxswmbhjfzzbl77nlxmj-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39322server: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test323??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.324 File "/nix/store/x4i03lhka9aiwxswmbhjfzzbl77nlxmj-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39325server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test, in 0.03 seconds)326(finished: run the VM test script, in 16.88 seconds)327server # [361817.245818] server unbound[302]: [302:0] info: service stopped (unbound 1.26.1).328server # [361817.245918] server unbound-control[340]: ok329server # [361817.246301] server unbound[302]: [302:0] info: server stats for thread 0: 2 queries, 1 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting330server # [361817.246309] server unbound[302]: [302:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0331server # [361817.246742] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.332server # [361817.246843] server data-mesher[220]: time=2026-10-13T15:35:20.204Z level=INFO msg=http_request uri=/files/dns/cnames status=204333server # [361817.246917] server systemd[1]: Finished Reload unbound zone configuration.334server # [361817.247493] server unbound[302]: [302:0] notice: Restart of unbound 1.26.1.335server # [361817.248491] server unbound[302]: [302:0] notice: init module 0: validator336server # [361817.248558] server unbound[302]: [302:0] notice: init module 1: iterator337server # [361817.253563] server unbound[302]: [302:0] info: start of service (unbound 1.26.1).338server # [361818.481289] server data-mesher[220]: time=2026-10-13T15:35:21.438Z level=DEBUG msg="attempting push/pull" peer_count=1339server # [361818.482036] server data-mesher[220]: time=2026-10-13T15:35:21.438Z level=DEBUG msg="initiating state exchange" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt timeout=5s340server # [361818.482036] server data-mesher[220]: time=2026-10-13T15:35:21.439Z level=INFO msg="received state sync from peer" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt341server # [361818.482036] server data-mesher[220]: time=2026-10-13T15:35:21.439Z level=INFO msg="merging remote state" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt342server # [361818.482660] server data-mesher[220]: time=2026-10-13T15:35:21.440Z level=INFO msg="merging remote state" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt343server # [361818.482660] server data-mesher[220]: time=2026-10-13T15:35:21.440Z level=INFO msg="state exchange complete" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt timeout=5s344server # [361818.482787] server data-mesher[220]: time=2026-10-13T15:35:21.440Z level=DEBUG msg="push/pull successful" interval=5s345server # [361818.482932] server data-mesher[220]: time=2026-10-13T15:35:21.440Z level=INFO msg="received file request" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt network="WiQ8iv8wTlBDwoz+2sfxE4yxkiVlYjIt3HjzaHxv0iw=" name=dns/cnames346server # [361818.485134] server data-mesher[220]: time=2026-10-13T15:35:21.442Z level=INFO msg="file transfer complete" peer=12D3KooWLdvX9YqYrjNPiDiF9ReWJN7AZxMvwYbZ4ovqkE9uk7Vt network="WiQ8iv8wTlBDwoz+2sfxE4yxkiVlYjIt3HjzaHxv0iw=" name=dns/cnames347client # [361818.481429] client data-mesher[211]: time=2026-10-13T15:35:21.438Z level=DEBUG msg="attempting push/pull" peer_count=1348client # [361818.481429] client data-mesher[211]: time=2026-10-13T15:35:21.439Z level=DEBUG msg="initiating state exchange" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7 timeout=5s349client # [361818.482198] client data-mesher[211]: time=2026-10-13T15:35:21.439Z level=INFO msg="received state sync from peer" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7350client # [361818.482198] client data-mesher[211]: time=2026-10-13T15:35:21.439Z level=INFO msg="merging remote state" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7351client # [361818.482198] client data-mesher[211]: time=2026-10-13T15:35:21.439Z level=DEBUG msg="new file detected" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7 name=dns/cnames name=dns/cnames352client # [361818.482360] client data-mesher[211]: time=2026-10-13T15:35:21.439Z level=INFO msg="scheduling file download" name=dns/cnames353client # [361818.482360] client data-mesher[211]: time=2026-10-13T15:35:21.439Z level=INFO msg="merging remote state" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7354client # [361818.482360] client data-mesher[211]: time=2026-10-13T15:35:21.439Z level=DEBUG msg="new file detected" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7 name=dns/cnames name=dns/cnames355client # [361818.482360] client data-mesher[211]: time=2026-10-13T15:35:21.439Z level=INFO msg="downloading file" name=dns/cnames signed_at="2026-10-13 15:35:20.151 +0000 UTC" signed_by="55AACN1NY9aZWmEiyN5Dd3p4Fu+m8emPOu6DpUC3ljc=" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7356client # [361818.482360] client data-mesher[211]: time=2026-10-13T15:35:21.439Z level=INFO msg="state exchange complete" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7 timeout=5s357client # [361818.482579] client data-mesher[211]: time=2026-10-13T15:35:21.440Z level=DEBUG msg="push/pull successful" interval=5s358client # [361818.490659] client systemd[1]: Starting Reload unbound zone configuration...359client # [361818.553443] client unbound[291]: [291:0] info: service stopped (unbound 1.26.1).360client # [361818.553932] client unbound-control[300]: ok361client # [361818.553997] client unbound[291]: [291:0] info: server stats for thread 0: 5 queries, 0 answers from cache, 5 recursions, 0 prefetch, 0 rejected by ip ratelimiting362client # [361818.554426] client data-mesher[211]: time=2026-10-13T15:35:21.511Z level=INFO msg="download complete" name=dns/cnames signed_at="2026-10-13 15:35:20.151 +0000 UTC" signed_by="55AACN1NY9aZWmEiyN5Dd3p4Fu+m8emPOu6DpUC3ljc=" peer=12D3KooWK4rpJ1WHRsj5RwrznNq86TeCHT1RJjHmZRnFxkRvksJ7 written=true elapsed=71.627228ms363client # [361818.554006] client unbound[291]: [291:0] info: server stats for thread 0: requestlist max 2 avg 1.6 exceeded 0 jostled 0364client # [361818.555411] client unbound[291]: [291:0] notice: Restart of unbound 1.26.1.365client # [361818.556465] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.366client # [361818.556735] client systemd[1]: Finished Reload unbound zone configuration.367client # [361818.558420] client unbound[291]: [291:0] notice: init module 0: validator368client # [361818.558511] client unbound[291]: [291:0] notice: init module 1: iterator369client # [361818.565065] client unbound[291]: [291:0] info: start of service (unbound 1.26.1).370test script finished in 19.60s371cleanup372kill NspawnMachine (pid 52)373kill NspawnMachine (pid 55)374Container client terminated by signal KILL.375Container server terminated by signal KILL.376(finished: cleanup, in 0.33 seconds)