container-test-run-dm-dns
default.checks.aarch64-linux.dm-dns
· build #393
· 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 # [6018459.884123] client systemd-journald[86]: Journal started27client # [6018459.884180] client systemd-journald[86]: Runtime Journal (/run/log/journal/1797525ac556495a8d6b869a6d5694f1) is 8M, max 2.5G, 2.4G free.28client # [6018459.897303] client systemd[1]: Finished Create Static Device Nodes in /dev gracefully.29client # [6018459.907469] client systemd[1]: Starting Flush Journal to Persistent Storage...30client # [6018459.908615] client systemd[1]: Starting Network Name Resolution...31client # [6018459.909487] client systemd[1]: Starting Create Static Device Nodes in /dev...32client # [6018459.918364] client systemd-journald[86]: Time spent on flushing to /var/log/journal/1797525ac556495a8d6b869a6d5694f1 is 1.690ms for 6 entries.33server # [6018459.884474] server systemd-journald[96]: Journal started34server # [6018459.884526] server systemd-journald[96]: Runtime Journal (/run/log/journal/c9365f316e2b4d6dbf2b146e2c884ef5) is 8M, max 2.5G, 2.4G free.35server # [6018459.897314] server systemd[1]: Finished Create Static Device Nodes in /dev gracefully.36server # [6018459.907468] server systemd[1]: Starting Flush Journal to Persistent Storage...37server # [6018459.908623] server systemd[1]: Starting Network Name Resolution...38server # [6018459.909484] server systemd[1]: Starting Create Static Device Nodes in /dev...39server # [6018459.919685] server systemd-journald[96]: Time spent on flushing to /var/log/journal/c9365f316e2b4d6dbf2b146e2c884ef5 is 1.537ms for 6 entries.40server # [6018459.919685] server systemd-journald[96]: System Journal (/var/log/journal/c9365f316e2b4d6dbf2b146e2c884ef5) is 8M, max 4G, 3.9G free.41server # [6018459.935184] server systemd[1]: Finished Create Static Device Nodes in /dev.42server # [6018459.935869] server systemd[1]: Reached target Preparation for Local File Systems.43server # [6018459.935980] server systemd[1]: Reached target Local File Systems.44server # [6018459.936824] server systemd[1]: Listening on Boot Loader Control Service Socket.45server # [6018459.936871] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container46server # [6018459.937812] server systemd[1]: Starting Save Transient machine-id to Disk...47server # [6018459.937851] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys48server # [6018459.957330] server systemd[1]: Finished Flush Journal to Persistent Storage.49server # [6018459.958861] server systemd[1]: Starting Create System Files and Directories...50server # [6018459.977546] server systemd-tmpfiles[158]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted51server # [6018459.977791] server systemd-tmpfiles[158]: fchmod() of /var/log/journal failed: Operation not permitted52server # [6018459.977985] server systemd-tmpfiles[158]: fchmod() of /var/log/journal/c9365f316e2b4d6dbf2b146e2c884ef5 failed: Operation not permitted53server # [6018459.978255] server systemd-tmpfiles[158]: fchmod() of /run/log/journal failed: Operation not permitted54client # [6018459.918364] client systemd-journald[86]: System Journal (/var/log/journal/1797525ac556495a8d6b869a6d5694f1) is 8M, max 4G, 3.9G free.55client # [6018459.935139] client systemd[1]: Finished Create Static Device Nodes in /dev.56client # [6018459.935833] client systemd[1]: Reached target Preparation for Local File Systems.57client # [6018459.935958] client systemd[1]: Reached target Local File Systems.58client # [6018459.936948] client systemd[1]: Listening on Boot Loader Control Service Socket.59client # [6018459.936999] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container60client # [6018459.937882] client systemd[1]: Starting Save Transient machine-id to Disk...61client # [6018459.937918] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys62client # [6018459.957936] client systemd[1]: Finished Flush Journal to Persistent Storage.63client # [6018459.958893] client systemd[1]: Starting Create System Files and Directories...64client # [6018459.977481] client systemd-tmpfiles[148]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted65client # [6018459.977742] client systemd-tmpfiles[148]: fchmod() of /var/log/journal failed: Operation not permitted66client # [6018459.977923] client systemd-tmpfiles[148]: fchmod() of /var/log/journal/1797525ac556495a8d6b869a6d5694f1 failed: Operation not permitted67client # [6018459.978192] client systemd-tmpfiles[148]: fchmod() of /run/log/journal failed: Operation not permitted68client # [6018459.979993] client systemd[1]: Finished Create System Files and Directories.69client # [6018459.981225] client systemd[1]: Starting Rebuild Journal Catalog...70client # [6018459.982075] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...71client # [6018459.993834] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.72client # [6018460.005328] client systemd[1]: Finished Rebuild Journal Catalog.73client # [6018460.006429] client systemd[1]: Starting Update is Completed...74client # [6018460.018133] client systemd[1]: Finished Update is Completed.75client # [6018460.044142] client systemd[1]: Finished Firewall.76client # [6018460.044298] client systemd[1]: Reached target Preparation for Network.77client # [6018460.044514] client systemd[1]: Listening on Network Management Resolve Hook Socket.78client # [6018460.045544] client systemd[1]: Starting Network Management...79server # [6018459.980029] server systemd[1]: Finished Create System Files and Directories.80server # [6018459.981223] server systemd[1]: Starting Rebuild Journal Catalog...81server # [6018459.982066] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...82server # [6018459.993829] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.83server # [6018460.009561] server systemd[1]: Finished Rebuild Journal Catalog.84server # [6018460.011252] server systemd[1]: Starting Update is Completed...85server # [6018460.024180] server systemd[1]: Finished Update is Completed.86server # [6018460.042410] server systemd[1]: Finished Firewall.87server # [6018460.042596] server systemd[1]: Reached target Preparation for Network.88server # [6018460.042915] server systemd[1]: Listening on Network Management Resolve Hook Socket.89server # [6018460.044148] server systemd[1]: Starting Network Management...90server # [6018460.190550] server systemd[1]: Finished Save Transient machine-id to Disk.91client # [6018460.191179] client systemd[1]: Finished Save Transient machine-id to Disk.92server # [6018460.518989] server systemd-networkd[213]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted93server # [6018460.519071] server systemd-networkd[213]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted94server # [6018460.525487] server systemd-networkd[213]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.95server # [6018460.525664] server systemd-networkd[213]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.96server # [6018460.525807] server systemd-networkd[213]: lo: Link UP97server # [6018460.525810] server systemd-networkd[213]: lo: Gained carrier98server # [6018460.525981] server systemd-networkd[213]: eth1: Configuring with /etc/systemd/network/40-eth1.network.99server # [6018460.526339] server systemd[1]: Started Network Management.100server # [6018460.526533] server systemd-networkd[213]: eth1: Link UP101server # [6018460.526847] server systemd-networkd[213]: eth1: Gained carrier102server # [6018460.527399] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...103server # [6018460.565140] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.104server # [6018460.739793] server systemd-resolved[124]: Positive Trust Anchors:105server # [6018460.739805] server systemd-resolved[124]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d106server # [6018460.739808] server systemd-resolved[124]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16107server # [6018460.739844] server systemd-resolved[124]: 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 test108server # [6018460.765517] server systemd-resolved[124]: Using system hostname 'server'.109server # [6018460.766966] server systemd[1]: Started Network Name Resolution.110server # [6018460.767060] server systemd[1]: Reached target Network.111server # [6018460.767127] server systemd[1]: Reached target System Initialization.112server # [6018460.767735] server systemd[1]: Started Watch for zone file changes.113server # [6018460.767774] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container114server # [6018460.767799] server systemd[1]: Started Daily Cleanup of Temporary Directories.115server # [6018460.767819] server systemd[1]: Reached target Path Units.116server # [6018460.767869] server systemd[1]: Reached target Timer Units.117server # [6018460.768063] server systemd[1]: Listening on D-Bus System Message Bus Socket.118server # [6018460.768207] server systemd[1]: Listening on Nix Daemon Socket.119server # [6018460.768360] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.120server # [6018460.768381] server systemd[1]: Reached target Socket Units.121server # [6018460.768424] server systemd[1]: Reached target Basic System.122server # [6018460.769811] server systemd[1]: Starting data mesher daemon...123client # [6018460.518590] client systemd-networkd[203]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted124client # [6018460.518681] client systemd-networkd[203]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted125client # [6018460.525413] client systemd-networkd[203]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.126client # [6018460.525577] client systemd-networkd[203]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section.127client # [6018460.525765] client systemd-networkd[203]: lo: Link UP128client # [6018460.525769] client systemd-networkd[203]: lo: Gained carrier129client # [6018460.525973] client systemd-networkd[203]: eth1: Configuring with /etc/systemd/network/40-eth1.network.130client # [6018460.526339] client systemd[1]: Started Network Management.131client # [6018460.526454] client systemd-networkd[203]: eth1: Link UP132client # [6018460.527061] client systemd-networkd[203]: eth1: Gained carrier133client # [6018460.527405] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd...134client # [6018460.565159] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd.135client # [6018460.757898] client systemd-resolved[114]: Positive Trust Anchors:136client # [6018460.757913] client systemd-resolved[114]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d137client # [6018460.757915] client systemd-resolved[114]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16138client # [6018460.757949] client systemd-resolved[114]: 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 test139client # [6018460.780522] client systemd-resolved[114]: Using system hostname 'client'.140server # [6018460.770695] server systemd[1]: Starting Import lastlog data into lastlog2 database...141server # [6018460.771542] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...142server # [6018460.772877] server systemd[1]: Starting D-Bus System Message Bus...143server # [6018460.830530] server systemd[1]: Finished Import lastlog data into lastlog2 database.144server # [6018460.873088] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.145server # [6018460.940371] server nsncd[221]: Aug 17 15:11:26.993 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"146server # [6018460.940462] server systemd[1]: Started Name Service Cache Daemon (nsncd).147server # [6018460.940523] server systemd[1]: Reached target User and Group Name Lookups.148server # [6018460.941790] server systemd[1]: Starting User Login Management...149server # [6018460.942454] server systemd[1]: Starting Permit User Sessions...150server # [6018460.996280] server systemd[1]: Finished Permit User Sessions.151server # [6018460.997549] server systemd[1]: Started Console Getty.152server # [6018460.997606] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0153server # [6018460.997633] server systemd[1]: Reached target Login Prompts.154client # [6018460.781915] client systemd[1]: Started Network Name Resolution.155client # [6018460.781988] client systemd[1]: Reached target Network.156client # [6018460.782056] client systemd[1]: Reached target System Initialization.157client # [6018460.782143] client systemd[1]: Started Watch for zone file changes.158client # [6018460.782169] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container159client # [6018460.782193] client systemd[1]: Started Daily Cleanup of Temporary Directories.160client # [6018460.782209] client systemd[1]: Reached target Path Units.161client # [6018460.782235] client systemd[1]: Reached target Timer Units.162client # [6018460.782351] client systemd[1]: Listening on D-Bus System Message Bus Socket.163client # [6018460.782457] client systemd[1]: Listening on Nix Daemon Socket.164client # [6018460.782561] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.165client # [6018460.782582] client systemd[1]: Reached target Socket Units.166client # [6018460.782615] client systemd[1]: Reached target Basic System.167client # [6018460.816470] client systemd[1]: Starting data mesher daemon...168client # [6018460.817395] client systemd[1]: Starting Import lastlog data into lastlog2 database...169client # [6018460.818216] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...170client # [6018460.819380] client systemd[1]: Starting D-Bus System Message Bus...171client # [6018460.835046] client systemd[1]: Finished Import lastlog data into lastlog2 database.172client # [6018460.873177] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.173client # [6018460.939092] client nsncd[211]: Aug 17 15:11:26.992 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"174client # [6018460.939198] client systemd[1]: Started Name Service Cache Daemon (nsncd).175client # [6018460.939266] client systemd[1]: Reached target User and Group Name Lookups.176client # [6018460.940619] client systemd[1]: Starting User Login Management...177client # [6018460.941385] client systemd[1]: Starting Permit User Sessions...178client # [6018460.995942] client systemd[1]: Finished Permit User Sessions.179client # [6018460.996996] client systemd[1]: Started Console Getty.180client # [6018460.997037] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0181client # [6018460.997053] client systemd[1]: Reached target Login Prompts.182client # [6018461.263637] client dbus-broker-launch[212]: Looking up NSS user entry for 'systemd-timesync'...183client # [6018461.264559] client dbus-broker-launch[212]: NSS returned no entry for 'systemd-timesync'184server # [6018461.256812] server dbus-broker-launch[222]: Looking up NSS user entry for 'systemd-timesync'...185server # [6018461.258216] server dbus-broker-launch[222]: NSS returned no entry for 'systemd-timesync'186server # [6018461.258216] server dbus-broker-launch[222]: Invalid user-name in /nix/store/c25qvcqpa12jav4il4k650d8f0748rlm-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"187server # [6018461.258293] server systemd[1]: Started D-Bus System Message Bus.188server # [6018461.265343] server dbus-broker-launch[222]: Ready189client # [6018461.264559] client dbus-broker-launch[212]: Invalid user-name in /nix/store/f5g540qdaklsx56qydy91v67zq6zizid-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"190client # [6018461.264913] client systemd[1]: Started D-Bus System Message Bus.191client # [6018461.272875] client dbus-broker-launch[212]: Ready192client # [6018461.604819] client data-mesher[209]: time=2026-08-17T15:11:27.657Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]193client # [6018461.606102] client data-mesher[209]: time=2026-08-17T15:11:27.659Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo: [/dns/client.test/tcp/7946]} {12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo194client # [6018461.606165] client data-mesher[209]: time=2026-08-17T15:11:27.659Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml195client # [6018461.667888] client data-mesher[209]: time=2026-08-17T15:11:27.720Z level=INFO msg="checking file integrity"196client # [6018461.667888] client data-mesher[209]: time=2026-08-17T15:11:27.720Z level=INFO msg="file integrity check complete"197client # [6018461.671920] client data-mesher[209]: time=2026-08-17T15:11:27.725Z level=INFO msg="libp2p host created" peer_id=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo 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 # [6018461.671979] client data-mesher[209]: time=2026-08-17T15:11:27.725Z level=INFO msg="registered HTTP route" method=GET path=/files199client # [6018461.671979] client data-mesher[209]: time=2026-08-17T15:11:27.725Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name200client # [6018461.671979] client data-mesher[209]: time=2026-08-17T15:11:27.725Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name201client # [6018461.671979] client data-mesher[209]: time=2026-08-17T15:11:27.725Z level=INFO msg="starting server"202client # [6018461.672116] client data-mesher[209]: time=2026-08-17T15:11:27.725Z level=INFO msg="HTTP server listening" address=[::1]:7331203client # [6018461.672147] client data-mesher[209]: time=2026-08-17T15:11:27.725Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331204client # [6018461.672251] client data-mesher[209]: time=2026-08-17T15:11:27.725Z level=INFO msg="waiting for DHT to populate" delay=10s205client # [6018461.678355] client data-mesher[209]: time=2026-08-17T15:11:27.731Z level=INFO msg="peer connected" peer_id=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL remote_addr=/ip4/192.168.1.2/tcp/7946206client # [6018461.705902] client data-mesher[209]: time=2026-08-17T15:11:27.759Z level=INFO msg="peer connected" peer_id=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL remote_addr=/ip4/192.168.1.2/tcp/7946207client # [6018461.850707] client systemd-logind[229]: New seat seat0.208client # [6018461.850905] client systemd[1]: Started User Login Management.209server # [6018461.655262] server data-mesher[219]: time=2026-08-17T15:11:27.708Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]210server # [6018461.656352] server data-mesher[219]: time=2026-08-17T15:11:27.709Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo: [/dns/client.test/tcp/7946]} {12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL: [/dns/server.test/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL211server # [6018461.656403] server data-mesher[219]: time=2026-08-17T15:11:27.709Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml212server # [6018461.668385] server data-mesher[219]: time=2026-08-17T15:11:27.721Z level=INFO msg="checking file integrity"213server # [6018461.668490] server data-mesher[219]: time=2026-08-17T15:11:27.721Z level=INFO msg="file integrity check complete"214server # [6018461.672467] server data-mesher[219]: time=2026-08-17T15:11:27.725Z level=INFO msg="libp2p host created" peer_id=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL 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]"215server # [6018461.672505] server data-mesher[219]: time=2026-08-17T15:11:27.725Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name216server # [6018461.672505] server data-mesher[219]: time=2026-08-17T15:11:27.725Z level=INFO msg="registered HTTP route" method=GET path=/files217server # [6018461.672505] server data-mesher[219]: time=2026-08-17T15:11:27.725Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name218server # [6018461.672505] server data-mesher[219]: time=2026-08-17T15:11:27.725Z level=INFO msg="starting server"219server # [6018461.672599] server data-mesher[219]: time=2026-08-17T15:11:27.725Z level=INFO msg="waiting for DHT to populate" delay=10s220server # [6018461.672742] server data-mesher[219]: time=2026-08-17T15:11:27.725Z level=INFO msg="HTTP server listening" address=[::1]:7331221server # [6018461.672807] server data-mesher[219]: time=2026-08-17T15:11:27.725Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331222server # [6018461.677699] server data-mesher[219]: time=2026-08-17T15:11:27.730Z level=INFO msg="peer connected" peer_id=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo remote_addr=/ip4/192.168.1.1/tcp/7946223server # [6018461.706805] server data-mesher[219]: time=2026-08-17T15:11:27.759Z level=INFO msg="peer connected" peer_id=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo remote_addr=/ip4/192.168.1.1/tcp/53816224server # [6018461.833334] server systemd-logind[239]: New seat seat0.225server # [6018461.833487] server systemd[1]: Started User Login Management.226server # [6018461.834629] server systemd[1]: Starting linger-users.service...227server # [6018461.888132] server systemd-networkd[213]: eth1: Gained IPv6LL228client # [6018461.856217] client systemd-networkd[203]: eth1: Gained IPv6LL229client # [6018461.896757] client systemd[1]: Starting linger-users.service...230client # [6018461.915228] client systemd[1]: linger-users.service: Deactivated successfully.231client # [6018461.915297] client systemd[1]: Finished linger-users.service.232server # [6018461.907286] server systemd[1]: linger-users.service: Deactivated successfully.233server # [6018461.907446] server systemd[1]: Finished linger-users.service.234server: still waiting for container 'server' to reach ready state...235client # [6018471.672322] client data-mesher[209]: time=2026-08-17T15:11:37.725Z level=INFO msg="performing state exchange with peers on join" count=1236client # [6018471.672711] client data-mesher[209]: time=2026-08-17T15:11:37.725Z level=DEBUG msg="initiating state exchange" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL timeout=5s237client # [6018471.673083] client data-mesher[209]: time=2026-08-17T15:11:37.726Z level=INFO msg="merging remote state" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL238client # [6018471.673083] client data-mesher[209]: time=2026-08-17T15:11:37.726Z level=INFO msg="state exchange complete" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL timeout=5s239client # [6018471.673083] client data-mesher[209]: time=2026-08-17T15:11:37.726Z level=INFO msg="received state sync from peer" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL240client # [6018471.673155] client data-mesher[209]: time=2026-08-17T15:11:37.726Z level=INFO msg="server started"241client # [6018471.673155] client data-mesher[209]: time=2026-08-17T15:11:37.726Z level=INFO msg="merging remote state" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL242client # [6018471.673217] client data-mesher[209]: time=2026-08-17T15:11:37.726Z level=INFO msg="starting expired-file sweeper" interval=1m0s243client # [6018471.673406] client systemd[1]: Started data mesher daemon.244client # [6018471.675657] client systemd[1]: Starting Unbound recursive Domain Name Server...245server # [6018471.672682] server data-mesher[219]: time=2026-08-17T15:11:37.725Z level=INFO msg="performing state exchange with peers on join" count=1246server # [6018471.673051] server data-mesher[219]: time=2026-08-17T15:11:37.725Z level=DEBUG msg="initiating state exchange" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo timeout=5s247server # [6018471.673051] server data-mesher[219]: time=2026-08-17T15:11:37.725Z level=INFO msg="received state sync from peer" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo248server # [6018471.673051] server data-mesher[219]: time=2026-08-17T15:11:37.725Z level=INFO msg="merging remote state" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo249server # [6018471.673358] server data-mesher[219]: time=2026-08-17T15:11:37.726Z level=INFO msg="merging remote state" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo250server # [6018471.673358] server data-mesher[219]: time=2026-08-17T15:11:37.726Z level=INFO msg="state exchange complete" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo timeout=5s251server # [6018471.673414] server data-mesher[219]: time=2026-08-17T15:11:37.726Z level=INFO msg="server started"252server # [6018471.673484] server data-mesher[219]: time=2026-08-17T15:11:37.726Z level=INFO msg="starting expired-file sweeper" interval=1m0s253server # [6018471.673582] server systemd[1]: Started data mesher daemon.254server # [6018471.674902] server systemd[1]: Starting Unbound recursive Domain Name Server...255client # [6018474.378734] client unbound-pre-start[271]: Root anchor updated!256client # [6018474.389063] client unbound-pre-start[275]: setup in directory /var/lib/unbound257server # [6018474.384681] server unbound-pre-start[283]: Root anchor updated!258server # [6018474.394626] server unbound-pre-start[287]: setup in directory /var/lib/unbound259server # [6018475.597362] server unbound-pre-start[296]: Certificate request self-signature ok260server # [6018475.597362] server unbound-pre-start[296]: subject=CN=unbound-control261server # [6018475.617939] server unbound-pre-start[287]: removing artifacts262server # [6018475.619366] server unbound-pre-start[287]: Setup success. Certificates created. Enable in unbound.conf file to use263server: (finished: waiting for unit unbound.service, in 17.65 seconds)264client: waiting for unit unbound.service265server # [6018476.321562] server unbound[300]: [300:0] notice: init module 0: validator266server # [6018476.321688] server unbound[300]: [300:0] notice: init module 1: iterator267server # [6018476.327579] server unbound[300]: [300:0] info: start of service (unbound 1.25.2).268server # [6018476.327711] server systemd[1]: Started Unbound recursive Domain Name Server.269server # [6018476.327979] server systemd[1]: Reached target Multi-User System.270server # [6018476.328132] server systemd[1]: Reached target Host and Network Name Lookups.271server # [6018476.357449] server systemd[1]: Starting Reload unbound zone configuration...272server # [6018476.369319] server unbound[300]: [300:0] info: service stopped (unbound 1.25.2).273server # [6018476.369615] server unbound-control[304]: ok274server # [6018476.369719] 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 ratelimiting275server # [6018476.369723] server unbound[300]: [300:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0276server # [6018476.370927] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.277server # [6018476.371171] server systemd[1]: Finished Reload unbound zone configuration.278server # [6018476.371506] server systemd[1]: Startup finished in 16.918s.279server # [6018476.371708] server unbound[300]: [300:0] notice: Restart of unbound 1.25.2.280server # [6018476.372682] server unbound[300]: [300:0] notice: init module 0: validator281server # [6018476.372746] server unbound[300]: [300:0] notice: init module 1: iterator282server # [6018476.377612] server unbound[300]: [300:0] info: start of service (unbound 1.25.2).283client # [6018476.525347] client unbound-pre-start[284]: Certificate request self-signature ok284client # [6018476.525347] client unbound-pre-start[284]: subject=CN=unbound-control285client # [6018476.543694] client unbound-pre-start[275]: removing artifacts286client # [6018476.545344] client unbound-pre-start[275]: Setup success. Certificates created. Enable in unbound.conf file to use287client # [6018476.673258] client data-mesher[209]: time=2026-08-17T15:11:42.726Z level=DEBUG msg="attempting push/pull" peer_count=1288client # [6018476.673602] client data-mesher[209]: time=2026-08-17T15:11:42.726Z level=DEBUG msg="initiating state exchange" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL timeout=5s289client # [6018476.673877] client data-mesher[209]: time=2026-08-17T15:11:42.727Z level=INFO msg="merging remote state" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL290client # [6018476.673877] client data-mesher[209]: time=2026-08-17T15:11:42.727Z level=INFO msg="state exchange complete" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL timeout=5s291client # [6018476.673946] client data-mesher[209]: time=2026-08-17T15:11:42.727Z level=DEBUG msg="push/pull successful" interval=5s292client # [6018476.674067] client data-mesher[209]: time=2026-08-17T15:11:42.727Z level=INFO msg="received state sync from peer" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL293client # [6018476.674067] client data-mesher[209]: time=2026-08-17T15:11:42.727Z level=INFO msg="merging remote state" peer=12D3KooWM8pZMcSEhtwp6cNpBGHszVoZviegDMVnLCqQUpwREVDL294server # [6018476.673662] server data-mesher[219]: time=2026-08-17T15:11:42.726Z level=DEBUG msg="attempting push/pull" peer_count=1295server # [6018476.673662] server data-mesher[219]: time=2026-08-17T15:11:42.726Z level=DEBUG msg="initiating state exchange" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo timeout=5s296server # [6018476.673996] server data-mesher[219]: time=2026-08-17T15:11:42.726Z level=INFO msg="received state sync from peer" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo297server # [6018476.673996] server data-mesher[219]: time=2026-08-17T15:11:42.726Z level=INFO msg="merging remote state" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo298server # [6018476.674220] server data-mesher[219]: time=2026-08-17T15:11:42.727Z level=INFO msg="merging remote state" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo299server # [6018476.674220] server data-mesher[219]: time=2026-08-17T15:11:42.727Z level=INFO msg="state exchange complete" peer=12D3KooWMurfSBh8poA91f672BwjKLahYRFvzdDMzxeCSmAtMYWo timeout=5s300server # [6018476.674282] server data-mesher[219]: time=2026-08-17T15:11:42.727Z level=DEBUG msg="push/pull successful" interval=5s301client: (finished: waiting for unit unbound.service, in 1.65 seconds)302server: waiting for unit data-mesher.service303server: (finished: waiting for unit data-mesher.service, in 0.01 seconds)304server: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1305server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1, in 0.03 seconds)306server: must succeed: data-mesher file update --network-id /nix/store/8wj77p7dx6frq1sac93hkz39xy7b3x98-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/cnames307server: (finished: must succeed: data-mesher file update --network-id /nix/store/8wj77p7dx6frq1sac93hkz39xy7b3x98-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)308??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.309 File "/nix/store/258dmf26bj4wx2idmzbn2vz4hzlmk8bh-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39310server: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test311??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.312 File "/nix/store/258dmf26bj4wx2idmzbn2vz4hzlmk8bh-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39313client # [6018478.074942] client unbound[289]: [289:0] notice: init module 0: validator314client # [6018478.075072] client unbound[289]: [289:0] notice: init module 1: iterator315client # [6018478.081510] client unbound[289]: [289:0] info: start of service (unbound 1.25.2).316client # [6018478.081644] client systemd[1]: Started Unbound recursive Domain Name Server.317client # [6018478.081903] client systemd[1]: Reached target Multi-User System.318client # [6018478.082027] client systemd[1]: Reached target Host and Network Name Lookups.319client # [6018478.083086] client systemd[1]: Starting Reload unbound zone configuration...320client # [6018478.136681] client unbound[289]: [289:0] info: service stopped (unbound 1.25.2).321client # [6018478.136995] client unbound-control[292]: ok322client # [6018478.137087] client unbound[289]: [289:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting323client # [6018478.137093] client unbound[289]: [289:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0324client # [6018478.138928] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.325client # [6018478.139100] client unbound[289]: [289:0] notice: Restart of unbound 1.25.2.326client # [6018478.139624] client systemd[1]: Finished Reload unbound zone configuration.327client # [6018478.140076] client systemd[1]: Startup finished in 18.697s.328client # [6018478.140143] client unbound[289]: [289:0] notice: init module 0: validator329client # [6018478.140223] client unbound[289]: [289:0] notice: init module 1: iterator330client # [6018478.145091] client unbound[289]: [289:0] info: start of service (unbound 1.25.2).331server # [6018478.318512] server systemd[1]: Starting Reload unbound zone configuration...332server # [6018478.320835] server data-mesher[219]: time=2026-08-17T15:11:44.373Z level=INFO msg=http_request uri=/files/dns/cnames status=204333server # [6018478.380120] server unbound[300]: [300:0] info: service stopped (unbound 1.25.2).334server # [6018478.380436] server unbound-control[340]: ok335server # [6018478.380561] server unbound[300]: [300:0] info: server stats for thread 0: 7 queries, 2 answers from cache, 5 recursions, 0 prefetch, 0 rejected by ip ratelimiting336server # [6018478.380566] server unbound[300]: [300:0] info: server stats for thread 0: requestlist max 2 avg 1.6 exceeded 0 jostled 0337server # [6018478.381155] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.338server # [6018478.381317] server systemd[1]: Finished Reload unbound zone configuration.339server # [6018478.383529] server unbound[300]: [300:0] notice: Restart of unbound 1.25.2.340server # [6018478.384812] server unbound[300]: [300:0] notice: init module 0: validator341server # [6018478.384882] server unbound[300]: [300:0] notice: init module 1: iterator342server # [6018478.389210] server unbound[300]: [300:0] info: start of service (unbound 1.25.2).343server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test, in 1.04 seconds)344(finished: run the VM test script, in 20.42 seconds)345test script finished in 20.47s346cleanup347kill NspawnMachine (pid 52)348kill NspawnMachine (pid 53)349Container client terminated by signal KILL.350Container server terminated by signal KILL.351(finished: cleanup, in 0.43 seconds)