Machine state will be reset. To keep it, pass --keep-machine-state
start all VLans
(finished: start all VLans, in 0.00 seconds)

Test will time out and terminate in 3600.0 seconds
run the VM test script
additionally exposed symbols:
    client, server,
    vlan1,
    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_ssh
start all VMs
client: systemd-nspawn running (pid 52)
server: systemd-nspawn running (pid 53)
client: Waiting for journal at /build/vm-state-client/var/log/journal...
server: Waiting for journal at /build/vm-state-server/var/log/journal...
(finished: start all VMs, in 0.00 seconds)
server: waiting for unit unbound.service
nixos-nspawn(server): TAP vde-tap1 not found; container will be isolated from VDE
nixos-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.
nixos-nspawn(client): TAP vde-tap1 not found; container will be isolated from VDE
nixos-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.
Note: 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.
Note: 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.
░ Spawning container server on /build/vm-state-server.
░ Spawning container client on /build/vm-state-client.
client # No journal boot entry found for the specified boot (+0).
server # No journal boot entry found for the specified boot (+0).
server # [7346580.372773] server systemd-journald[96]: Journal started
server # [7346580.372825] server systemd-journald[96]: Runtime Journal (/run/log/journal/047c49c1ff2c408da7886719c01a88f0) is 8M, max 2.5G, 2.4G free.
server # [7346580.379797] server systemd[1]: Starting Flush Journal to Persistent Storage...
server # [7346580.380551] server systemd[1]: Starting Network Name Resolution...
server # [7346580.381230] server systemd[1]: Starting Create Static Device Nodes in /dev...
server # [7346580.390664] server systemd-journald[96]: Time spent on flushing to /var/log/journal/047c49c1ff2c408da7886719c01a88f0 is 2.621ms for 5 entries.
server # [7346580.390664] server systemd-journald[96]: System Journal (/var/log/journal/047c49c1ff2c408da7886719c01a88f0) is 8M, max 4G, 3.9G free.
server # [7346580.396562] server systemd[1]: Finished Create Static Device Nodes in /dev.
server # [7346580.396791] server systemd[1]: Reached target Preparation for Local File Systems.
server # [7346580.396877] server systemd[1]: Reached target Local File Systems.
server # [7346580.397595] server systemd[1]: Listening on Boot Loader Control Service Socket.
server # [7346580.397641] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container
server # [7346580.398444] server systemd[1]: Starting Save Transient machine-id to Disk...
server # [7346580.398477] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys
server # [7346580.552354] server systemd[1]: Finished Flush Journal to Persistent Storage.
server # [7346580.552548] server systemd[1]: Finished Firewall.
server # [7346580.554221] server systemd[1]: Reached target Preparation for Network.
server # [7346580.554768] server systemd[1]: Listening on Network Management Resolve Hook Socket.
server # [7346580.556050] server systemd[1]: Starting Network Management...
server # [7346580.556894] server systemd[1]: Starting Create System Files and Directories...
server # [7346580.574227] server systemd-tmpfiles[206]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted
server # [7346580.574446] server systemd-tmpfiles[206]: fchmod() of /var/log/journal failed: Operation not permitted
server # [7346580.574591] server systemd-tmpfiles[206]: fchmod() of /var/log/journal/047c49c1ff2c408da7886719c01a88f0 failed: Operation not permitted
server # [7346580.574811] server systemd-tmpfiles[206]: fchmod() of /run/log/journal failed: Operation not permitted
server # [7346580.576894] server systemd[1]: Finished Create System Files and Directories.
server # [7346580.578521] server systemd[1]: Starting Rebuild Journal Catalog...
server # [7346580.579665] server systemd[1]: Starting Record System Boot/Shutdown in UTMP...
server # [7346580.596262] server systemd[1]: Finished Record System Boot/Shutdown in UTMP.
server # [7346580.602162] server systemd[1]: Finished Rebuild Journal Catalog.
server # [7346580.603874] server systemd[1]: Starting Update is Completed...
server # [7346580.617064] server systemd[1]: Finished Update is Completed.
server # [7346580.958788] server systemd-networkd[205]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted
server # [7346580.958880] server systemd-networkd[205]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted
server # [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.
server # [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.
server # [7346580.965709] server systemd-networkd[205]: lo: Link UP
server # [7346580.965714] server systemd-networkd[205]: lo: Gained carrier
server # [7346580.965909] server systemd-networkd[205]: eth1: Configuring with /etc/systemd/network/40-eth1.network.
server # [7346580.966316] server systemd[1]: Started Network Management.
server # [7346580.996348] server systemd-networkd[205]: eth1: Link UP
server # [7346580.996652] server systemd-networkd[205]: eth1: Gained carrier
server # [7346580.997104] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd...
client # [7346580.372531] client systemd-journald[87]: Journal started
client # [7346580.372588] client systemd-journald[87]: Runtime Journal (/run/log/journal/00c87ae786e0479b81fea911d692e0c1) is 8M, max 2.5G, 2.4G free.
server # [7346581.026419] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd.
server # [7346581.035000] server systemd-resolved[118]: Positive Trust Anchors:
client # [7346580.379720] client systemd[1]: Starting Flush Journal to Persistent Storage...
server # [7346581.035010] server systemd-resolved[118]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
client # [7346580.380581] client systemd[1]: Starting Network Name Resolution...
server # [7346581.035013] server systemd-resolved[118]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16
client # [7346580.381394] client systemd[1]: Starting Create Static Device Nodes in /dev...
server # [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 test
client # [7346580.390569] client systemd-journald[87]: Time spent on flushing to /var/log/journal/00c87ae786e0479b81fea911d692e0c1 is 2.396ms for 5 entries.
server # [7346581.056802] server systemd-resolved[118]: Using system hostname 'server'.
client # [7346580.390569] client systemd-journald[87]: System Journal (/var/log/journal/00c87ae786e0479b81fea911d692e0c1) is 8M, max 4G, 3.9G free.
server # [7346581.058191] server systemd[1]: Started Network Name Resolution.
client # [7346580.396819] client systemd[1]: Finished Create Static Device Nodes in /dev.
server # [7346581.058314] server systemd[1]: Reached target Network.
client # [7346580.397040] client systemd[1]: Reached target Preparation for Local File Systems.
server # [7346581.058436] server systemd[1]: Reached target System Initialization.
client # [7346580.397122] client systemd[1]: Reached target Local File Systems.
server # [7346581.058597] server systemd[1]: Started Watch for zone file changes.
client # [7346580.397823] client systemd[1]: Listening on Boot Loader Control Service Socket.
server # [7346581.058652] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container
client # [7346580.397864] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container
server # [7346581.058707] server systemd[1]: Started Daily Cleanup of Temporary Directories.
client # [7346580.398640] client systemd[1]: Starting Save Transient machine-id to Disk...
server # [7346581.058747] server systemd[1]: Reached target Path Units.
client # [7346580.398671] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys
server # [7346581.058815] server systemd[1]: Reached target Timer Units.
client # [7346580.499942] client systemd[1]: Finished Flush Journal to Persistent Storage.
server # [7346581.059047] server systemd[1]: Listening on D-Bus System Message Bus Socket.
client # [7346580.501442] client systemd[1]: Starting Create System Files and Directories...
server # [7346581.060801] server systemd[1]: Listening on Nix Daemon Socket.
client # [7346580.552376] client systemd[1]: Finished Firewall.
server # [7346581.061055] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.
client # [7346580.552622] client systemd[1]: Reached target Preparation for Network.
server # [7346581.061110] server systemd[1]: Reached target Socket Units.
client # [7346580.552827] client systemd[1]: Listening on Network Management Resolve Hook Socket.
server # [7346581.061201] server systemd[1]: Reached target Basic System.
client # [7346580.553864] client systemd[1]: Starting Network Management...
server # [7346581.063335] server systemd[1]: Starting data mesher daemon...
client # [7346580.565746] client systemd-tmpfiles[179]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted
server # [7346581.064572] server systemd[1]: Starting Import lastlog data into lastlog2 database...
client # [7346580.565979] client systemd-tmpfiles[179]: fchmod() of /var/log/journal failed: Operation not permitted
server # [7346581.065807] server systemd[1]: Starting Name Service Cache Daemon (nsncd)...
client # [7346580.566142] client systemd-tmpfiles[179]: fchmod() of /var/log/journal/00c87ae786e0479b81fea911d692e0c1 failed: Operation not permitted
server # [7346581.067746] server systemd[1]: Starting D-Bus System Message Bus...
client # [7346580.566387] client systemd-tmpfiles[179]: fchmod() of /run/log/journal failed: Operation not permitted
server # [7346581.086987] server systemd[1]: Finished Import lastlog data into lastlog2 database.
client # [7346580.568272] client systemd[1]: Finished Create System Files and Directories.
server # [7346581.134359] server systemd[1]: Finished Save Transient machine-id to Disk.
client # [7346580.570323] client systemd[1]: Starting Rebuild Journal Catalog...
server # [7346581.175988] server systemd[1]: Started Name Service Cache Daemon (nsncd).
client # [7346580.571652] client systemd[1]: Starting Record System Boot/Shutdown in UTMP...
server # [7346581.176069] server systemd[1]: Reached target User and Group Name Lookups.
client # [7346580.588145] client systemd[1]: Finished Record System Boot/Shutdown in UTMP.
server # [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"
client # [7346580.592556] client systemd[1]: Finished Rebuild Journal Catalog.
server # [7346581.208594] server systemd[1]: Starting User Login Management...
client # [7346580.594222] client systemd[1]: Starting Update is Completed...
server # [7346581.209675] server systemd[1]: Starting Permit User Sessions...
client # [7346580.604692] client systemd[1]: Finished Update is Completed.
server # [7346581.219672] server systemd[1]: Finished Permit User Sessions.
client # [7346580.940187] client systemd-networkd[197]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted
server # [7346581.221229] server systemd[1]: Started Console Getty.
client # [7346580.940278] client systemd-networkd[197]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted
server # [7346581.221298] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0
client # [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.
server # [7346581.221341] server systemd[1]: Reached target Login Prompts.
client # [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.
server # [7346581.241238] server dbus-broker-launch[221]: Looking up NSS user entry for 'systemd-timesync'...
client # [7346580.948423] client systemd-networkd[197]: lo: Link UP
server # [7346581.242542] server dbus-broker-launch[221]: NSS returned no entry for 'systemd-timesync'
client # [7346580.948426] client systemd-networkd[197]: lo: Gained carrier
server # [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"
client # [7346580.948603] client systemd-networkd[197]: eth1: Configuring with /etc/systemd/network/40-eth1.network.
server # [7346581.242989] server systemd[1]: Started D-Bus System Message Bus.
client # [7346580.949010] client systemd[1]: Started Network Management.
server # [7346581.250395] server dbus-broker-launch[221]: Ready
client # [7346580.949082] client systemd-networkd[197]: eth1: Link UP
server # [7346581.367132] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
client # [7346580.949387] client systemd-networkd[197]: eth1: Gained carrier
client # [7346580.950664] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd...
client # [7346581.007122] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd.
client # [7346581.013385] client systemd-resolved[109]: Positive Trust Anchors:
client # [7346581.013396] client systemd-resolved[109]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
client # [7346581.013400] client systemd-resolved[109]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16
client # [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 test
client # [7346581.036032] client systemd-resolved[109]: Using system hostname 'client'.
client # [7346581.037342] client systemd[1]: Started Network Name Resolution.
client # [7346581.037447] client systemd[1]: Reached target Network.
client # [7346581.037548] client systemd[1]: Reached target System Initialization.
client # [7346581.037676] client systemd[1]: Started Watch for zone file changes.
client # [7346581.037724] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container
client # [7346581.037762] client systemd[1]: Started Daily Cleanup of Temporary Directories.
client # [7346581.037788] client systemd[1]: Reached target Path Units.
client # [7346581.037836] client systemd[1]: Reached target Timer Units.
client # [7346581.038001] client systemd[1]: Listening on D-Bus System Message Bus Socket.
client # [7346581.038176] client systemd[1]: Listening on Nix Daemon Socket.
client # [7346581.038334] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.
client # [7346581.038370] client systemd[1]: Reached target Socket Units.
client # [7346581.038425] client systemd[1]: Reached target Basic System.
client # [7346581.040140] client systemd[1]: Starting data mesher daemon...
client # [7346581.041146] client systemd[1]: Starting Import lastlog data into lastlog2 database...
client # [7346581.042217] client systemd[1]: Starting Name Service Cache Daemon (nsncd)...
client # [7346581.043913] client systemd[1]: Starting D-Bus System Message Bus...
client # [7346581.061902] client systemd[1]: Finished Import lastlog data into lastlog2 database.
client # [7346581.134715] client systemd[1]: Finished Save Transient machine-id to Disk.
client # [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"
client # [7346581.149282] client systemd[1]: Started Name Service Cache Daemon (nsncd).
client # [7346581.149392] client systemd[1]: Reached target User and Group Name Lookups.
client # [7346581.151425] client systemd[1]: Starting User Login Management...
client # [7346581.152723] client systemd[1]: Starting Permit User Sessions...
client # [7346581.215912] client systemd[1]: Finished Permit User Sessions.
client # [7346581.217562] client systemd[1]: Started Console Getty.
client # [7346581.217629] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0
client # [7346581.217668] client systemd[1]: Reached target Login Prompts.
client # [7346581.243817] client dbus-broker-launch[212]: Looking up NSS user entry for 'systemd-timesync'...
client # [7346581.245009] client dbus-broker-launch[212]: NSS returned no entry for 'systemd-timesync'
client # [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"
client # [7346581.245750] client systemd[1]: Started D-Bus System Message Bus.
client # [7346581.253380] client dbus-broker-launch[212]: Ready
client # [7346581.366385] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
client # [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]
client # [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=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK
client # [7346581.489869] client data-mesher[209]: time=2026-09-02T00:06:47.543Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml
client # [7346581.610102] client data-mesher[209]: time=2026-09-02T00:06:47.663Z level=INFO msg="checking file integrity"
client # [7346581.610333] client data-mesher[209]: time=2026-09-02T00:06:47.663Z level=INFO msg="file integrity check complete"
client # [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]"
client # [7346581.618802] client data-mesher[209]: time=2026-09-02T00:06:47.671Z level=INFO msg="registered HTTP route" method=GET path=/files
client # [7346581.618802] client data-mesher[209]: time=2026-09-02T00:06:47.671Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name
client # [7346581.618802] client data-mesher[209]: time=2026-09-02T00:06:47.671Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name
client # [7346581.618802] client data-mesher[209]: time=2026-09-02T00:06:47.671Z level=INFO msg="starting server"
client # [7346581.619172] client data-mesher[209]: time=2026-09-02T00:06:47.672Z level=INFO msg="HTTP server listening" address=[::1]:7331
client # [7346581.619257] client data-mesher[209]: time=2026-09-02T00:06:47.672Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331
client # [7346581.619408] client data-mesher[209]: time=2026-09-02T00:06:47.672Z level=INFO msg="waiting for DHT to populate" delay=10s
client # [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/7946
client # [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/7946
client # [7346581.665121] client systemd-logind[230]: New seat seat0.
client # [7346581.665334] client systemd[1]: Started User Login Management.
client # [7346581.716742] client systemd[1]: Starting linger-users.service...
client # [7346581.730103] client systemd[1]: linger-users.service: Deactivated successfully.
client # [7346581.730225] client systemd[1]: Finished linger-users.service.
server # [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]
server # [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=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1
server # [7346581.505191] server data-mesher[218]: time=2026-09-02T00:06:47.558Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml
server # [7346581.610399] server data-mesher[218]: time=2026-09-02T00:06:47.663Z level=INFO msg="checking file integrity"
server # [7346581.610577] server data-mesher[218]: time=2026-09-02T00:06:47.663Z level=INFO msg="file integrity check complete"
server # [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]"
server # [7346581.616341] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="registered HTTP route" method=GET path=/files
server # [7346581.616341] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name
server # [7346581.616414] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name
server # [7346581.616414] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="starting server"
server # [7346581.616488] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="waiting for DHT to populate" delay=10s
server # [7346581.616620] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="HTTP server listening" address=[::1]:7331
server # [7346581.616668] server data-mesher[218]: time=2026-09-02T00:06:47.669Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331
server # [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/7946
server # [7346581.644378] server systemd-logind[239]: New seat seat0.
server # [7346581.644503] server systemd[1]: Started User Login Management.
server # [7346581.645746] server systemd[1]: Starting linger-users.service...
server # [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/43934
server # [7346581.726254] server systemd[1]: linger-users.service: Deactivated successfully.
server # [7346581.726530] server systemd[1]: Finished linger-users.service.
client # [7346582.212208] client systemd-networkd[197]: eth1: Gained IPv6LL
server # [7346582.852264] server systemd-networkd[205]: eth1: Gained IPv6LL
server: still waiting for container 'server' to reach ready state...
client # [7346591.617354] client data-mesher[209]: time=2026-09-02T00:06:57.670Z level=INFO msg="received state sync from peer" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1
client # [7346591.617354] client data-mesher[209]: time=2026-09-02T00:06:57.670Z level=INFO msg="merging remote state" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1
server # [7346591.616562] server data-mesher[218]: time=2026-09-02T00:06:57.669Z level=INFO msg="performing state exchange with peers on join" count=1
server # [7346591.616562] server data-mesher[218]: time=2026-09-02T00:06:57.669Z level=DEBUG msg="initiating state exchange" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK timeout=5s
server # [7346591.617709] server data-mesher[218]: time=2026-09-02T00:06:57.670Z level=INFO msg="merging remote state" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK
client # [7346591.621233] client data-mesher[209]: time=2026-09-02T00:06:57.674Z level=INFO msg="performing state exchange with peers on join" count=1
client # [7346591.621342] client data-mesher[209]: time=2026-09-02T00:06:57.674Z level=DEBUG msg="initiating state exchange" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 timeout=5s
client # [7346591.621840] client data-mesher[209]: time=2026-09-02T00:06:57.674Z level=INFO msg="merging remote state" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1
client # [7346591.621840] client data-mesher[209]: time=2026-09-02T00:06:57.675Z level=INFO msg="state exchange complete" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 timeout=5s
client # [7346591.621968] client data-mesher[209]: time=2026-09-02T00:06:57.675Z level=INFO msg="server started"
server # [7346591.617709] server data-mesher[218]: time=2026-09-02T00:06:57.670Z level=INFO msg="state exchange complete" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK timeout=5s
server # [7346591.617781] server data-mesher[218]: time=2026-09-02T00:06:57.670Z level=INFO msg="server started"
server # [7346591.617917] server data-mesher[218]: time=2026-09-02T00:06:57.671Z level=INFO msg="starting expired-file sweeper" interval=1m0s
client # [7346591.622023] client data-mesher[209]: time=2026-09-02T00:06:57.675Z level=INFO msg="starting expired-file sweeper" interval=1m0s
server # [7346591.618068] server systemd[1]: Started data mesher daemon.
client # [7346591.622163] client systemd[1]: Started data mesher daemon.
server # [7346591.620433] server systemd[1]: Starting Unbound recursive Domain Name Server...
client # [7346591.624450] client systemd[1]: Starting Unbound recursive Domain Name Server...
server # [7346591.621659] server data-mesher[218]: time=2026-09-02T00:06:57.674Z level=INFO msg="received state sync from peer" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK
server # [7346591.621659] server data-mesher[218]: time=2026-09-02T00:06:57.674Z level=INFO msg="merging remote state" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK
client # [7346592.527899] client unbound-pre-start[272]: Root anchor updated!
client # [7346592.542798] client unbound-pre-start[276]: setup in directory /var/lib/unbound
server # [7346592.575693] server unbound-pre-start[281]: Root anchor updated!
server # [7346592.587838] server unbound-pre-start[285]: setup in directory /var/lib/unbound
server # [7346593.500404] server unbound-pre-start[294]: Certificate request self-signature ok
server # [7346593.500404] server unbound-pre-start[294]: subject=CN=unbound-control
server # [7346593.518230] server unbound-pre-start[285]: removing artifacts
server # [7346593.519799] server unbound-pre-start[285]: Setup success. Certificates created. Enable in unbound.conf file to use
server: (finished: waiting for unit unbound.service, in 14.66 seconds)
client: waiting for unit unbound.service
server # [7346594.023620] server unbound[299]: [299:0] notice: init module 0: validator
server # [7346594.023736] server unbound[299]: [299:0] notice: init module 1: iterator
server # [7346594.029450] server unbound[299]: [299:0] info: start of service (unbound 1.26.0).
server # [7346594.029649] server systemd[1]: Started Unbound recursive Domain Name Server.
server # [7346594.030183] server systemd[1]: Reached target Multi-User System.
server # [7346594.030456] server systemd[1]: Reached target Host and Network Name Lookups.
server # [7346594.032190] server systemd[1]: Starting Reload unbound zone configuration...
server # [7346594.042917] server unbound[299]: [299:0] info: service stopped (unbound 1.26.0).
server # [7346594.043047] server unbound-control[302]: ok
server # [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 ratelimiting
server # [7346594.043271] server unbound[299]: [299:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0
server # [7346594.043923] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.
server # [7346594.044090] server systemd[1]: Finished Reload unbound zone configuration.
server # [7346594.044344] server systemd[1]: Startup finished in 14.129s.
server # [7346594.045081] server unbound[299]: [299:0] notice: Restart of unbound 1.26.0.
server # [7346594.045980] server unbound[299]: [299:0] notice: init module 0: validator
server # [7346594.046039] server unbound[299]: [299:0] notice: init module 1: iterator
server # [7346594.050589] server unbound[299]: [299:0] info: start of service (unbound 1.26.0).
client # [7346594.672538] client unbound-pre-start[285]: Certificate request self-signature ok
client # [7346594.672538] client unbound-pre-start[285]: subject=CN=unbound-control
client # [7346594.689608] client unbound-pre-start[276]: removing artifacts
client # [7346594.691058] client unbound-pre-start[276]: Setup success. Certificates created. Enable in unbound.conf file to use
client # [7346595.143582] client unbound[290]: [290:0] notice: init module 0: validator
client # [7346595.143700] client unbound[290]: [290:0] notice: init module 1: iterator
client # [7346595.149265] client unbound[290]: [290:0] info: start of service (unbound 1.26.0).
client # [7346595.149397] client systemd[1]: Started Unbound recursive Domain Name Server.
client # [7346595.149731] client systemd[1]: Reached target Multi-User System.
client # [7346595.149902] client systemd[1]: Reached target Host and Network Name Lookups.
client # [7346595.151104] client systemd[1]: Starting Reload unbound zone configuration...
client # [7346595.245118] client unbound[290]: [290:0] info: service stopped (unbound 1.26.0).
client # [7346595.245453] client unbound-control[293]: ok
client # [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 ratelimiting
client # [7346595.245459] client unbound[290]: [290:0] info: server stats for thread 0: requestlist max 1 avg 1 exceeded 0 jostled 0
client # [7346595.246579] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.
client # [7346595.246746] client systemd[1]: Finished Reload unbound zone configuration.
client # [7346595.247064] client systemd[1]: Startup finished in 15.336s.
client # [7346595.247161] client unbound[290]: [290:0] notice: Restart of unbound 1.26.0.
client # [7346595.248043] client unbound[290]: [290:0] notice: init module 0: validator
client # [7346595.248104] client unbound[290]: [290:0] notice: init module 1: iterator
client # [7346595.252621] client unbound[290]: [290:0] info: start of service (unbound 1.26.0).
client: (finished: waiting for unit unbound.service, in 1.65 seconds)
server: waiting for unit data-mesher.service
server: (finished: waiting for unit data-mesher.service, in 0.01 seconds)
server: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1
server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 server.test A | grep 10.0.0.1, in 0.02 seconds)
server: 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
server: (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)
??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/pg5lbaicpvf34wrdmfh8riwp8avk7lk6-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
server: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test
??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead.
    File "/nix/store/pg5lbaicpvf34wrdmfh8riwp8avk7lk6-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39
server: (finished: waiting for success: dig +short @127.0.0.1 -p 5353 myapp.test CNAME | grep server.test, in 0.03 seconds)
(finished: run the VM test script, in 16.64 seconds)
server # [7346595.781012] server systemd[1]: Starting Reload unbound zone configuration...
server # [7346595.793037] server systemd[1]: unbound-reload-zones.service: Deactivated successfully.
server # [7346595.792531] server unbound[299]: [299:0] info: service stopped (unbound 1.26.0).
server # [7346595.793228] server systemd[1]: Finished Reload unbound zone configuration.
server # [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 ratelimiting
server # [7346595.807148] server unbound-control[337]: ok
server # [7346595.793074] server unbound[299]: [299:0] info: server stats for thread 0: requestlist max 2 avg 1.6 exceeded 0 jostled 0
server # [7346595.794859] server unbound[299]: [299:0] notice: Restart of unbound 1.26.0.
server # [7346595.796610] server unbound[299]: [299:0] notice: init module 0: validator
server # [7346595.796701] server unbound[299]: [299:0] notice: init module 1: iterator
server # [7346595.804385] server unbound[299]: [299:0] info: start of service (unbound 1.26.0).
server # [7346596.014899] server data-mesher[218]: time=2026-09-02T00:07:02.068Z level=INFO msg=http_request uri=/files/dns/cnames status=204
server # [7346596.617959] server data-mesher[218]: time=2026-09-02T00:07:02.671Z level=DEBUG msg="attempting push/pull" peer_count=1
server # [7346596.618193] server data-mesher[218]: time=2026-09-02T00:07:02.671Z level=DEBUG msg="initiating state exchange" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK timeout=5s
server # [7346596.620029] server data-mesher[218]: time=2026-09-02T00:07:02.673Z level=INFO msg="merging remote state" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK
server # [7346596.620029] server data-mesher[218]: time=2026-09-02T00:07:02.673Z level=INFO msg="state exchange complete" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK timeout=5s
server # [7346596.620229] server data-mesher[218]: time=2026-09-02T00:07:02.673Z level=DEBUG msg="push/pull successful" interval=5s
server # [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/cnames
server # [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/cnames
server # [7346596.623435] server data-mesher[218]: time=2026-09-02T00:07:02.676Z level=INFO msg="received state sync from peer" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK
server # [7346596.623435] server data-mesher[218]: time=2026-09-02T00:07:02.676Z level=INFO msg="merging remote state" peer=12D3KooWGHypAPKWzoA1qDanYHhXXJLtz75wmunWc69kH58drcGK
client # [7346596.619851] client data-mesher[209]: time=2026-09-02T00:07:02.672Z level=INFO msg="received state sync from peer" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1
client # [7346596.619851] client data-mesher[209]: time=2026-09-02T00:07:02.672Z level=INFO msg="merging remote state" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1
client # [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/cnames
client # [7346596.619851] client data-mesher[209]: time=2026-09-02T00:07:02.673Z level=INFO msg="scheduling file download" name=dns/cnames
client # [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=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1
client # [7346596.622650] client data-mesher[209]: time=2026-09-02T00:07:02.675Z level=DEBUG msg="attempting push/pull" peer_count=1
client # [7346596.622755] client data-mesher[209]: time=2026-09-02T00:07:02.675Z level=DEBUG msg="initiating state exchange" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 timeout=5s
client # [7346596.623796] client data-mesher[209]: time=2026-09-02T00:07:02.676Z level=INFO msg="merging remote state" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1
client # [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/cnames
client # [7346596.623872] client data-mesher[209]: time=2026-09-02T00:07:02.676Z level=INFO msg="state exchange complete" peer=12D3KooWBgGLBAACQNMLkaZd1dpvKCRXntJpiyfTgeLWUnnBN8B1 timeout=5s
client # [7346596.623872] client data-mesher[209]: time=2026-09-02T00:07:02.677Z level=DEBUG msg="push/pull successful" interval=5s
client # [7346596.627381] client systemd[1]: Starting Reload unbound zone configuration...
client # [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.729936ms
client # [7346596.849086] client unbound[290]: [290:0] info: service stopped (unbound 1.26.0).
client # [7346596.849582] client unbound-control[300]: ok
client # [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 ratelimiting
client # [7346596.849732] client unbound[290]: [290:0] info: server stats for thread 0: requestlist max 2 avg 1.6 exceeded 0 jostled 0
client # [7346596.851886] client unbound[290]: [290:0] notice: Restart of unbound 1.26.0.
client # [7346596.852732] client systemd[1]: unbound-reload-zones.service: Deactivated successfully.
client # [7346596.852995] client systemd[1]: Finished Reload unbound zone configuration.
client # [7346596.856227] client unbound[290]: [290:0] notice: init module 0: validator
client # [7346596.856345] client unbound[290]: [290:0] notice: init module 1: iterator
client # [7346596.867329] client unbound[290]: [290:0] info: start of service (unbound 1.26.0).
test script finished in 18.23s
cleanup
kill NspawnMachine (pid 52)
kill NspawnMachine (pid 53)
Container client terminated by signal KILL.
(finished: cleanup, in 0.33 seconds)
Container server terminated by signal KILL.