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:
    controller, peer1, peer2,
    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
controller: systemd-nspawn running (pid 50)
controller: Waiting for journal at /build/vm-state-controller/var/log/journal...
peer1: systemd-nspawn running (pid 53)
peer1: Waiting for journal at /build/vm-state-peer1/var/log/journal...
controller: waiting for unit data-mesher.service
nixos-nspawn(controller): TAP vde-tap1 not found; container will be isolated from VDE
nixos-nspawn(controller): 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(peer1): TAP vde-tap1 not found; container will be isolated from VDE
nixos-nspawn(peer1): 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.
░ Spawning container controller on /build/vm-state-controller.
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 peer1 on /build/vm-state-peer1.
controller # No journal files were found.
controller # No journal boot entry found for the specified boot (+0).
peer1 # No journal files were found.
peer1 # No journal boot entry found for the specified boot (+0).
controller # [7504940.364157] controller systemd-journald[105]: Journal started
controller # [7504940.364235] controller systemd-journald[105]: Runtime Journal (/run/log/journal/e75dc48847bc44bea34335b9fdd3fed7) is 8M, max 2.5G, 2.4G free.
controller # [7504940.369920] controller systemd[1]: Finished Create Static Device Nodes in /dev gracefully.
controller # [7504940.380171] controller systemd[1]: Starting Flush Journal to Persistent Storage...
controller # [7504940.381146] controller systemd[1]: Starting Network Name Resolution...
controller # [7504940.381845] controller systemd[1]: Starting Create Static Device Nodes in /dev...
controller # [7504940.390805] controller systemd-journald[105]: Time spent on flushing to /var/log/journal/e75dc48847bc44bea34335b9fdd3fed7 is 1.417ms for 6 entries.
controller # [7504940.390805] controller systemd-journald[105]: System Journal (/var/log/journal/e75dc48847bc44bea34335b9fdd3fed7) is 8M, max 4G, 3.9G free.
controller # [7504940.396902] controller systemd[1]: Finished Create Static Device Nodes in /dev.
controller # [7504940.397133] controller systemd[1]: Reached target Preparation for Local File Systems.
controller # [7504940.397222] controller systemd[1]: Reached target Local File Systems.
controller # [7504940.397951] controller systemd[1]: Listening on Boot Loader Control Service Socket.
controller # [7504940.397995] controller systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container
controller # [7504940.398902] controller systemd[1]: Starting Save Transient machine-id to Disk...
controller # [7504940.398931] controller systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys
controller # [7504940.410195] controller systemd[1]: Finished Flush Journal to Persistent Storage.
controller # [7504940.411620] controller systemd[1]: Starting Create System Files and Directories...
controller # [7504940.429162] controller systemd-tmpfiles[153]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted
controller # [7504940.429374] controller systemd-tmpfiles[153]: fchmod() of /var/log/journal failed: Operation not permitted
controller # [7504940.429521] controller systemd-tmpfiles[153]: fchmod() of /var/log/journal/e75dc48847bc44bea34335b9fdd3fed7 failed: Operation not permitted
controller # [7504940.429748] controller systemd-tmpfiles[153]: fchmod() of /run/log/journal failed: Operation not permitted
controller # [7504940.431251] controller systemd[1]: Finished Create System Files and Directories.
controller # [7504940.432215] controller systemd[1]: Starting Rebuild Journal Catalog...
controller # [7504940.432905] controller systemd[1]: Starting Record System Boot/Shutdown in UTMP...
controller # [7504940.446061] controller systemd[1]: Finished Record System Boot/Shutdown in UTMP.
controller # [7504940.450740] controller systemd[1]: Finished Save Transient machine-id to Disk.
controller # [7504940.450956] controller systemd[1]: Finished Rebuild Journal Catalog.
controller # [7504940.452523] controller systemd[1]: Starting Update is Completed...
controller # [7504940.463823] controller systemd[1]: Finished Update is Completed.
controller # [7504940.530694] controller systemd[1]: Finished Firewall.
controller # [7504940.530838] controller systemd[1]: Reached target Preparation for Network.
controller # [7504940.531058] controller systemd[1]: Listening on Network Management Resolve Hook Socket.
controller # [7504940.532063] controller systemd[1]: Starting Network Management...
controller # [7504940.905144] controller systemd-networkd[225]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted
controller # [7504940.905232] controller systemd-networkd[225]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted
controller # [7504940.912346] controller systemd-networkd[225]: /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.
controller # [7504940.912506] controller systemd-networkd[225]: /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.
controller # [7504940.912652] controller systemd-networkd[225]: lo: Link UP
controller # [7504940.912655] controller systemd-networkd[225]: lo: Gained carrier
controller # [7504940.912851] controller systemd-networkd[225]: eth1: Configuring with /etc/systemd/network/40-eth1.network.
controller # [7504940.913207] controller systemd[1]: Started Network Management.
controller # [7504940.949074] controller systemd[1]: Starting Enable Persistent Storage in systemd-networkd...
controller # [7504940.949637] controller systemd-networkd[225]: wg-star: Configuring with /etc/systemd/network/40-wg-star.network.
controller # [7504940.949981] controller systemd-networkd[225]: wg-star: netdev ready
controller # [7504940.950454] controller systemd-networkd[225]: eth1: Link UP
controller # [7504940.950823] controller systemd-networkd[225]: eth1: Gained carrier
controller # [7504940.997014] controller systemd-networkd[225]: wg-star: Link UP
controller # [7504940.997019] controller systemd-networkd[225]: wg-star: Gained carrier
controller # [7504940.997422] controller systemd[1]: Finished Enable Persistent Storage in systemd-networkd.
controller # [7504941.077500] controller systemd-resolved[131]: Positive Trust Anchors:
controller # [7504941.077511] controller systemd-resolved[131]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
controller # [7504941.077514] controller systemd-resolved[131]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16
controller # [7504941.077550] controller 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 test
controller # [7504941.099344] controller systemd-resolved[131]: Using system hostname 'controller'.
peer1 # [7504940.355855] peer1 systemd-journald[95]: Journal started
peer1 # [7504940.355916] peer1 systemd-journald[95]: Runtime Journal (/run/log/journal/35452c24d07644489f884994d0e1731c) is 8M, max 2.5G, 2.4G free.
peer1 # [7504940.359416] peer1 systemd[1]: Finished Create Static Device Nodes in /dev gracefully.
controller # [7504941.101562] controller systemd[1]: Started Network Name Resolution.
peer1 # [7504940.369799] peer1 systemd[1]: Starting Flush Journal to Persistent Storage...
controller # [7504941.101645] controller systemd[1]: Reached target Network.
peer1 # [7504940.370949] peer1 systemd[1]: Starting Network Name Resolution...
controller # [7504941.101725] controller systemd[1]: Reached target System Initialization.
peer1 # [7504940.371845] peer1 systemd[1]: Starting Create Static Device Nodes in /dev...
controller # [7504941.101843] controller systemd[1]: Started Watch for WireGuard peer changes from data-mesher.
controller # [7504941.101874] controller systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container
controller # [7504941.101898] controller systemd[1]: Started Daily Cleanup of Temporary Directories.
controller # [7504941.101918] controller systemd[1]: Reached target Path Units.
controller # [7504941.101960] controller systemd[1]: Reached target Timer Units.
peer1 # [7504940.378256] peer1 systemd-journald[95]: Time spent on flushing to /var/log/journal/35452c24d07644489f884994d0e1731c is 3.081ms for 6 entries.
controller # [7504941.102135] controller systemd[1]: Listening on D-Bus System Message Bus Socket.
peer1 # [7504940.378256] peer1 systemd-journald[95]: System Journal (/var/log/journal/35452c24d07644489f884994d0e1731c) is 8M, max 4G, 3.9G free.
controller # [7504941.102274] controller systemd[1]: Listening on Nix Daemon Socket.
controller # [7504941.102456] controller systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.
controller # [7504941.102479] controller systemd[1]: Reached target Socket Units.
controller # [7504941.102524] controller systemd[1]: Reached target Basic System.
controller # [7504941.104046] controller systemd[1]: Starting data mesher daemon...
controller # [7504941.105100] controller systemd[1]: Starting Import lastlog data into lastlog2 database...
controller # [7504941.106008] controller systemd[1]: Starting Name Service Cache Daemon (nsncd)...
controller # [7504941.107284] controller systemd[1]: Starting D-Bus System Message Bus...
controller # [7504941.162428] controller systemd[1]: Finished Import lastlog data into lastlog2 database.
controller # [7504941.273497] controller systemd[1]: Started Name Service Cache Daemon (nsncd).
controller # [7504941.273973] controller nsncd[232]: Sep 03 20:06:07.326 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
controller # [7504941.273604] controller systemd[1]: Reached target Host and Network Name Lookups.
controller # [7504941.273691] controller systemd[1]: Reached target User and Group Name Lookups.
controller # [7504941.275780] controller systemd[1]: Starting User Login Management...
controller # [7504941.277057] controller systemd[1]: Starting Permit User Sessions...
peer1 # [7504940.387588] peer1 systemd[1]: Finished Create Static Device Nodes in /dev.
peer1 # [7504940.387832] peer1 systemd[1]: Reached target Preparation for Local File Systems.
peer1 # [7504940.387929] peer1 systemd[1]: Reached target Local File Systems.
peer1 # [7504940.388742] peer1 systemd[1]: Listening on Boot Loader Control Service Socket.
peer1 # [7504940.388791] peer1 systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container
peer1 # [7504940.389642] peer1 systemd[1]: Starting Save Transient machine-id to Disk...
peer1 # [7504940.389675] peer1 systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys
peer1 # [7504940.402789] peer1 systemd[1]: Finished Flush Journal to Persistent Storage.
peer1 # [7504940.404291] peer1 systemd[1]: Starting Create System Files and Directories...
peer1 # [7504940.423666] peer1 systemd-tmpfiles[144]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted
peer1 # [7504940.423884] peer1 systemd-tmpfiles[144]: fchmod() of /var/log/journal failed: Operation not permitted
peer1 # [7504940.424051] peer1 systemd-tmpfiles[144]: fchmod() of /var/log/journal/35452c24d07644489f884994d0e1731c failed: Operation not permitted
peer1 # [7504940.424286] peer1 systemd-tmpfiles[144]: fchmod() of /run/log/journal failed: Operation not permitted
peer1 # [7504940.425834] peer1 systemd[1]: Finished Create System Files and Directories.
peer1 # [7504940.427019] peer1 systemd[1]: Starting Rebuild Journal Catalog...
peer1 # [7504940.427953] peer1 systemd[1]: Starting Record System Boot/Shutdown in UTMP...
peer1 # [7504940.441398] peer1 systemd[1]: Finished Record System Boot/Shutdown in UTMP.
peer1 # [7504940.447569] peer1 systemd[1]: Finished Rebuild Journal Catalog.
peer1 # [7504940.449018] peer1 systemd[1]: Starting Update is Completed...
peer1 # [7504940.451083] peer1 systemd[1]: Finished Save Transient machine-id to Disk.
peer1 # [7504940.459208] peer1 systemd[1]: Finished Update is Completed.
peer1 # [7504940.512475] peer1 systemd[1]: Finished Firewall.
peer1 # [7504940.512569] peer1 systemd[1]: Reached target Preparation for Network.
peer1 # [7504940.512791] peer1 systemd[1]: Listening on Network Management Resolve Hook Socket.
peer1 # [7504940.513829] peer1 systemd[1]: Starting Network Management...
peer1 # [7504940.890921] peer1 systemd-networkd[213]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted
peer1 # [7504940.891011] peer1 systemd-networkd[213]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted
peer1 # [7504940.899572] peer1 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.
peer1 # [7504940.899743] peer1 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.
peer1 # [7504940.899904] peer1 systemd-networkd[213]: lo: Link UP
peer1 # [7504940.899909] peer1 systemd-networkd[213]: lo: Gained carrier
peer1 # [7504940.900139] peer1 systemd-networkd[213]: eth1: Configuring with /etc/systemd/network/40-eth1.network.
peer1 # [7504940.900514] peer1 systemd[1]: Started Network Management.
peer1 # [7504940.948843] peer1 systemd[1]: Starting Enable Persistent Storage in systemd-networkd...
peer1 # [7504940.949637] peer1 systemd-networkd[213]: wg-star: Configuring with /etc/systemd/network/40-wg-star.network.
peer1 # [7504940.949984] peer1 systemd-networkd[213]: wg-star: netdev ready
peer1 # [7504940.950775] peer1 systemd-networkd[213]: eth1: Link UP
peer1 # [7504940.951003] peer1 systemd-networkd[213]: eth1: Gained carrier
peer1 # [7504940.981391] peer1 systemd-networkd[213]: wg-star: Link UP
peer1 # [7504940.981397] peer1 systemd-networkd[213]: wg-star: Gained carrier
peer1 # [7504940.981872] peer1 systemd[1]: Finished Enable Persistent Storage in systemd-networkd.
peer1 # [7504941.074514] peer1 systemd-resolved[121]: Positive Trust Anchors:
peer1 # [7504941.074524] peer1 systemd-resolved[121]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
peer1 # [7504941.074527] peer1 systemd-resolved[121]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16
peer1 # [7504941.074562] peer1 systemd-resolved[121]: 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
peer1 # [7504941.097763] peer1 systemd-resolved[121]: Using system hostname 'peer1'.
peer1 # [7504941.099663] peer1 systemd[1]: Started Network Name Resolution.
peer1 # [7504941.099755] peer1 systemd[1]: Reached target Network.
peer1 # [7504941.099834] peer1 systemd[1]: Reached target System Initialization.
peer1 # [7504941.099958] peer1 systemd[1]: Started Watch for WireGuard controller info from data-mesher.
peer1 # [7504941.099992] peer1 systemd[1]: Started Periodic heartbeat re-publish for dm-wireguard-star peer.
peer1 # [7504941.100038] peer1 systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container
peer1 # [7504941.100063] peer1 systemd[1]: Started Daily Cleanup of Temporary Directories.
peer1 # [7504941.100085] peer1 systemd[1]: Reached target Path Units.
peer1 # [7504941.100349] peer1 systemd[1]: Reached target Timer Units.
peer1 # [7504941.100562] peer1 systemd[1]: Listening on D-Bus System Message Bus Socket.
peer1 # [7504941.100715] peer1 systemd[1]: Listening on Nix Daemon Socket.
peer1 # [7504941.100906] peer1 systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.
peer1 # [7504941.100933] peer1 systemd[1]: Reached target Socket Units.
peer1 # [7504941.100985] peer1 systemd[1]: Reached target Basic System.
peer1 # [7504941.102616] peer1 systemd[1]: Starting data mesher daemon...
peer1 # [7504941.103654] peer1 systemd[1]: Starting Import lastlog data into lastlog2 database...
peer1 # [7504941.104891] peer1 systemd[1]: Starting Name Service Cache Daemon (nsncd)...
peer1 # [7504941.106351] peer1 systemd[1]: Starting D-Bus System Message Bus...
peer1 # [7504941.162283] peer1 systemd[1]: Finished Import lastlog data into lastlog2 database.
peer1 # [7504941.271653] peer1 systemd[1]: Started Name Service Cache Daemon (nsncd).
peer1 # [7504941.271757] peer1 systemd[1]: Reached target Host and Network Name Lookups.
peer1 # [7504941.271834] peer1 nsncd[220]: Sep 03 20:06:07.324 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
peer1 # [7504941.271854] peer1 systemd[1]: Reached target User and Group Name Lookups.
peer1 # [7504941.273834] peer1 systemd[1]: Starting User Login Management...
peer1 # [7504941.275229] peer1 systemd[1]: Starting Permit User Sessions...
controller # [7504941.329519] controller systemd[1]: Finished Permit User Sessions.
controller # [7504941.331108] controller systemd[1]: Started Console Getty.
controller # [7504941.331182] controller systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0
controller # [7504941.331223] controller systemd[1]: Reached target Login Prompts.
controller # [7504941.356754] controller dbus-broker-launch[233]: Looking up NSS user entry for 'systemd-timesync'...
controller # [7504941.358082] controller systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
controller # [7504941.360093] controller dbus-broker-launch[233]: NSS returned no entry for 'systemd-timesync'
controller # [7504941.360093] controller dbus-broker-launch[233]: Invalid user-name in /nix/store/xsr87dgy2kj3mg3fn4f91cnqa6qwvd21-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"
controller # [7504941.360687] controller systemd[1]: Started D-Bus System Message Bus.
controller # [7504941.368419] controller dbus-broker-launch[233]: Ready
peer1 # [7504941.327953] peer1 systemd[1]: Finished Permit User Sessions.
peer1 # [7504941.329654] peer1 systemd[1]: Started Console Getty.
peer1 # [7504941.329729] peer1 systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0
peer1 # [7504941.329778] peer1 systemd[1]: Reached target Login Prompts.
peer1 # [7504941.348135] peer1 systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
peer1 # [7504941.358651] peer1 dbus-broker-launch[221]: Looking up NSS user entry for 'systemd-timesync'...
peer1 # [7504941.360284] peer1 dbus-broker-launch[221]: NSS returned no entry for 'systemd-timesync'
peer1 # [7504941.360284] peer1 dbus-broker-launch[221]: Invalid user-name in /nix/store/xsr87dgy2kj3mg3fn4f91cnqa6qwvd21-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"
peer1 # [7504941.360900] peer1 systemd[1]: Started D-Bus System Message Bus.
peer1 # [7504941.369228] peer1 dbus-broker-launch[221]: Ready
peer1 # [7504941.589475] peer1 data-mesher[218]: time=2026-09-03T20:06:07.642Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]
peer1 # [7504941.590481] peer1 data-mesher[218]: time=2026-09-03T20:06:07.643Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466: [/dns/controller.clan/tcp/7946]} {12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2: [/dns/peer1.clan/tcp/7946]} {12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt: [/dns/peer2.clan/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
peer1 # [7504941.590481] peer1 data-mesher[218]: time=2026-09-03T20:06:07.643Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml
peer1 # [7504941.601885] peer1 data-mesher[218]: time=2026-09-03T20:06:07.655Z level=INFO msg="checking file integrity"
peer1 # [7504941.602002] peer1 data-mesher[218]: time=2026-09-03T20:06:07.655Z level=INFO msg="file integrity check complete"
peer1 # [7504941.605676] peer1 data-mesher[218]: time=2026-09-03T20:06:07.658Z level=INFO msg="libp2p host created" peer_id=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 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 /ip6/fda1:5c8::35fa:39:d6ca:cb57/tcp/7946]"
peer1 # [7504941.605757] peer1 data-mesher[218]: time=2026-09-03T20:06:07.658Z level=INFO msg="registered HTTP route" method=GET path=/files
peer1 # [7504941.605757] peer1 data-mesher[218]: time=2026-09-03T20:06:07.658Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name
peer1 # [7504941.605757] peer1 data-mesher[218]: time=2026-09-03T20:06:07.658Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name
peer1 # [7504941.605757] peer1 data-mesher[218]: time=2026-09-03T20:06:07.658Z level=INFO msg="starting server"
peer1 # [7504941.605931] peer1 data-mesher[218]: time=2026-09-03T20:06:07.658Z level=INFO msg="waiting for DHT to populate" delay=10s
peer1 # [7504941.605931] peer1 data-mesher[218]: time=2026-09-03T20:06:07.659Z level=INFO msg="HTTP server listening" address=[::1]:7331
peer1 # [7504941.606395] peer1 data-mesher[218]: time=2026-09-03T20:06:07.659Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331
peer1 # [7504941.612694] peer1 data-mesher[218]: time=2026-09-03T20:06:07.665Z level=INFO msg="peer connected" peer_id=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 remote_addr=/ip4/192.168.1.1/tcp/7946
peer1 # [7504941.614411] peer1 data-mesher[218]: time=2026-09-03T20:06:07.667Z level=INFO msg="peer connected" peer_id=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 remote_addr=/ip4/192.168.1.1/tcp/47494
peer1 # [7504941.732130] peer1 systemd-logind[238]: New seat seat0.
peer1 # [7504941.732318] peer1 systemd[1]: Started User Login Management.
peer1 # [7504941.734438] peer1 systemd[1]: Starting linger-users.service...
peer1 # [7504941.770006] peer1 systemd[1]: linger-users.service: Deactivated successfully.
peer1 # [7504941.770127] peer1 systemd[1]: Finished linger-users.service.
controller # [7504941.589176] controller data-mesher[230]: time=2026-09-03T20:06:07.642Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]
controller # [7504941.590247] controller data-mesher[230]: time=2026-09-03T20:06:07.643Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466: [/dns/controller.clan/tcp/7946]} {12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2: [/dns/peer1.clan/tcp/7946]} {12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt: [/dns/peer2.clan/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
controller # [7504941.590314] controller data-mesher[230]: time=2026-09-03T20:06:07.643Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml
controller # [7504941.601754] controller data-mesher[230]: time=2026-09-03T20:06:07.654Z level=INFO msg="checking file integrity"
controller # [7504941.601870] controller data-mesher[230]: time=2026-09-03T20:06:07.655Z level=INFO msg="file integrity check complete"
controller # [7504941.605738] controller data-mesher[230]: time=2026-09-03T20:06:07.658Z level=INFO msg="libp2p host created" peer_id=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 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 /ip6/fda1:5c8::8347:d476:2a4b:65b7/tcp/7946]"
controller # [7504941.605786] controller data-mesher[230]: time=2026-09-03T20:06:07.658Z level=INFO msg="registered HTTP route" method=GET path=/files
controller # [7504941.605786] controller data-mesher[230]: time=2026-09-03T20:06:07.658Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name
controller # [7504941.605786] controller data-mesher[230]: time=2026-09-03T20:06:07.658Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name
controller # [7504941.605786] controller data-mesher[230]: time=2026-09-03T20:06:07.658Z level=INFO msg="starting server"
controller # [7504941.606030] controller data-mesher[230]: time=2026-09-03T20:06:07.659Z level=INFO msg="HTTP server listening" address=[::1]:7331
controller # [7504941.606073] controller data-mesher[230]: time=2026-09-03T20:06:07.659Z level=INFO msg="waiting for DHT to populate" delay=10s
controller # [7504941.606106] controller data-mesher[230]: time=2026-09-03T20:06:07.659Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331
controller # [7504941.614198] controller data-mesher[230]: time=2026-09-03T20:06:07.666Z level=INFO msg="peer connected" peer_id=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 remote_addr=/ip4/192.168.1.2/tcp/7946
controller # [7504941.614918] controller data-mesher[230]: time=2026-09-03T20:06:07.668Z level=INFO msg="peer connected" peer_id=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 remote_addr=/ip4/192.168.1.2/tcp/7946
controller # [7504941.732130] controller systemd-logind[250]: New seat seat0.
controller # [7504941.732317] controller systemd[1]: Started User Login Management.
controller # [7504941.734554] controller systemd[1]: Starting linger-users.service...
controller # [7504941.769635] controller systemd[1]: linger-users.service: Deactivated successfully.
controller # [7504941.769856] controller systemd[1]: Finished linger-users.service.
peer1 # [7504942.532504] peer1 systemd-networkd[213]: eth1: Gained IPv6LL
controller # [7504942.688250] controller systemd-networkd[225]: eth1: Gained IPv6LL
controller: still waiting for container 'controller' to reach ready state...
peer1 # [7504951.606424] peer1 data-mesher[218]: time=2026-09-03T20:06:17.659Z level=INFO msg="performing state exchange with peers on join" count=1
peer1 # [7504951.607137] peer1 data-mesher[218]: time=2026-09-03T20:06:17.659Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504951.607636] peer1 data-mesher[218]: time=2026-09-03T20:06:17.660Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504951.607636] peer1 data-mesher[218]: time=2026-09-03T20:06:17.660Z level=INFO msg="state exchange complete" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504951.607758] peer1 data-mesher[218]: time=2026-09-03T20:06:17.660Z level=INFO msg="received state sync from peer" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504951.607758] peer1 data-mesher[218]: time=2026-09-03T20:06:17.660Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504951.607758] peer1 data-mesher[218]: time=2026-09-03T20:06:17.660Z level=INFO msg="server started"
peer1 # [7504951.607891] peer1 data-mesher[218]: time=2026-09-03T20:06:17.660Z level=INFO msg="starting expired-file sweeper" interval=1m0s
peer1 # [7504951.608239] peer1 systemd[1]: Started data mesher daemon.
peer1 # [7504951.610083] peer1 systemd[1]: Starting Publish WireGuard peer info to data-mesher...
peer1 # [7504951.772543] peer1 data-mesher[218]: time=2026-09-03T20:06:17.825Z level=INFO msg=http_request uri=/files/dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk status=204
peer1 # [7504951.772763] peer1 dm-wg-star-publish[283]: Status: 204 No Content
peer1 # [7504951.774355] peer1 systemd[1]: Starting Reconfigure WireGuard with controller from data-mesher...
peer1 # [7504951.776440] peer1 systemd[1]: dm-wg-star-wg-star-publish.service: Deactivated successfully.
peer1 # [7504951.776615] peer1 systemd[1]: Finished Publish WireGuard peer info to data-mesher.
peer1 # [7504951.777141] peer1 systemd[1]: Reached target Multi-User System.
controller: (finished: waiting for unit data-mesher.service, in 12.67 seconds)
peer1: waiting for unit data-mesher.service
peer1: (finished: waiting for unit data-mesher.service, in 0.02 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
controller: waiting for success: test -f /var/lib/data-mesher/files/home/dm_wg_star_wg_star/controller
??? 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
controller: (finished: waiting for success: test -f /var/lib/data-mesher/files/home/dm_wg_star_wg_star/controller, in 0.01 seconds)
peer1: waiting for success: test -f /var/lib/data-mesher/files/home/dm_wg_star_wg_star/controller
controller # [7504951.606993] controller data-mesher[230]: time=2026-09-03T20:06:17.660Z level=INFO msg="performing state exchange with peers on join" count=1
controller # [7504951.607662] controller data-mesher[230]: time=2026-09-03T20:06:17.660Z level=DEBUG msg="initiating state exchange" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 timeout=5s
controller # [7504951.607662] controller data-mesher[230]: time=2026-09-03T20:06:17.660Z level=INFO msg="received state sync from peer" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504951.607662] controller data-mesher[230]: time=2026-09-03T20:06:17.660Z level=INFO msg="merging remote state" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504951.607877] controller data-mesher[230]: time=2026-09-03T20:06:17.661Z level=INFO msg="merging remote state" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504951.607877] controller data-mesher[230]: time=2026-09-03T20:06:17.661Z level=INFO msg="state exchange complete" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 timeout=5s
controller # [7504951.607997] controller data-mesher[230]: time=2026-09-03T20:06:17.661Z level=INFO msg="server started"
controller # [7504951.608105] controller data-mesher[230]: time=2026-09-03T20:06:17.661Z level=INFO msg="starting expired-file sweeper" interval=1m0s
controller # [7504951.608193] controller systemd[1]: Started data mesher daemon.
controller # [7504951.610311] controller systemd[1]: Starting Publish WireGuard controller info to data-mesher...
controller # [7504951.687486] controller systemd[1]: Starting Reconfigure WireGuard peers from data-mesher...
controller # [7504951.737763] controller data-mesher[230]: time=2026-09-03T20:06:17.790Z level=INFO msg=http_request uri=/files/dm_wg_star_wg_star/controller status=204
controller # [7504951.737919] controller dm-wg-star-publish[294]: Status: 204 No Content
controller # [7504951.742094] controller systemd[1]: Finished Publish WireGuard controller info to data-mesher.
controller # [7504951.742862] controller systemd[1]: Reached target Multi-User System.
controller # [7504951.777530] controller dm-wg-star-reconfig[320]: No peer data available yet, skipping
controller # [7504951.778915] controller systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully.
controller # [7504951.816275] controller systemd[1]: Finished Reconfigure WireGuard peers from data-mesher.
controller # [7504951.816799] controller systemd[1]: Startup finished in 11.931s.
peer1 # [7504951.905992] peer1 dm-wg-star-reconfig[311]: No controller data available yet, skipping
peer1 # [7504951.907338] peer1 systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully.
peer1 # [7504951.907498] peer1 systemd[1]: Finished Reconfigure WireGuard with controller from data-mesher.
peer1 # [7504951.908046] peer1 systemd[1]: Startup finished in 12.040s.
peer1 # [7504956.608930] peer1 data-mesher[218]: time=2026-09-03T20:06:22.662Z level=DEBUG msg="attempting push/pull" peer_count=1
peer1 # [7504956.609580] peer1 data-mesher[218]: time=2026-09-03T20:06:22.662Z level=INFO msg="received state sync from peer" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504956.609580] peer1 data-mesher[218]: time=2026-09-03T20:06:22.662Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504956.609580] peer1 data-mesher[218]: time=2026-09-03T20:06:22.662Z level=DEBUG msg="new file detected" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 name=dm_wg_star_wg_star/controller name=dm_wg_star_wg_star/controller
peer1 # [7504956.609580] peer1 data-mesher[218]: time=2026-09-03T20:06:22.662Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504956.609580] peer1 data-mesher[218]: time=2026-09-03T20:06:22.662Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/controller
peer1 # [7504956.609580] peer1 data-mesher[218]: time=2026-09-03T20:06:22.662Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/controller signed_at="2026-09-03 20:06:17.734 +0000 UTC" signed_by="nPzNL9EwkbvuZIKP5H2nx8SyUYpgCLnMm1a4dWKOCpQ=" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504956.611358] peer1 data-mesher[218]: time=2026-09-03T20:06:22.664Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504956.611445] peer1 data-mesher[218]: time=2026-09-03T20:06:22.664Z level=DEBUG msg="new file detected" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 name=dm_wg_star_wg_star/controller name=dm_wg_star_wg_star/controller
peer1 # [7504956.611445] peer1 data-mesher[218]: time=2026-09-03T20:06:22.664Z level=INFO msg="state exchange complete" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504956.611445] peer1 data-mesher[218]: time=2026-09-03T20:06:22.664Z level=DEBUG msg="push/pull successful" interval=5s
peer1 # [7504956.612662] peer1 data-mesher[218]: time=2026-09-03T20:06:22.665Z level=INFO msg="received file request" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk
peer1 # [7504956.615041] peer1 data-mesher[218]: time=2026-09-03T20:06:22.668Z level=INFO msg="file transfer complete" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk
peer1 # [7504956.618516] peer1 systemd[1]: Starting Reconfigure WireGuard with controller from data-mesher...
peer1 # [7504956.627636] peer1 data-mesher[218]: time=2026-09-03T20:06:22.680Z level=INFO msg="download complete" name=dm_wg_star_wg_star/controller signed_at="2026-09-03 20:06:17.734 +0000 UTC" signed_by="nPzNL9EwkbvuZIKP5H2nx8SyUYpgCLnMm1a4dWKOCpQ=" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 written=true elapsed=18.199283ms
peer1 # [7504956.782590] peer1 systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully.
peer1 # [7504956.782740] peer1 systemd[1]: Finished Reconfigure WireGuard with controller from data-mesher.
controller # [7504956.608261] controller data-mesher[230]: time=2026-09-03T20:06:22.661Z level=DEBUG msg="attempting push/pull" peer_count=1
controller # [7504956.608944] controller data-mesher[230]: time=2026-09-03T20:06:22.661Z level=DEBUG msg="initiating state exchange" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 timeout=5s
controller # [7504956.609496] controller data-mesher[230]: time=2026-09-03T20:06:22.662Z level=INFO msg="merging remote state" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504956.609619] controller data-mesher[230]: time=2026-09-03T20:06:22.662Z level=INFO msg="received state sync from peer" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504956.609619] controller data-mesher[230]: time=2026-09-03T20:06:22.662Z level=INFO msg="merging remote state" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504956.609912] controller data-mesher[230]: time=2026-09-03T20:06:22.663Z level=INFO msg="received file request" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/controller
controller # [7504956.610866] controller data-mesher[230]: time=2026-09-03T20:06:22.663Z level=DEBUG msg="new file detected" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk
controller # [7504956.610931] controller data-mesher[230]: time=2026-09-03T20:06:22.664Z level=DEBUG msg="new file detected" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk
controller # [7504956.610931] controller data-mesher[230]: time=2026-09-03T20:06:22.664Z level=INFO msg="state exchange complete" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 timeout=5s
controller # [7504956.611060] controller data-mesher[230]: time=2026-09-03T20:06:22.664Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk
controller # [7504956.611270] controller data-mesher[230]: time=2026-09-03T20:06:22.664Z level=DEBUG msg="push/pull successful" interval=5s
controller # [7504956.611337] controller data-mesher[230]: time=2026-09-03T20:06:22.664Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk signed_at="2026-09-03 20:06:17.822 +0000 UTC" signed_by="mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk=" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504956.612428] controller data-mesher[230]: time=2026-09-03T20:06:22.665Z level=INFO msg="file transfer complete" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/controller
controller # [7504956.622897] controller systemd[1]: Starting Reconfigure WireGuard peers from data-mesher...
controller # [7504956.627592] controller data-mesher[230]: time=2026-09-03T20:06:22.680Z level=INFO msg="download complete" name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk signed_at="2026-09-03 20:06:17.822 +0000 UTC" signed_by="mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk=" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 written=true elapsed=16.418859ms
controller # [7504956.780707] controller systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully.
controller # [7504956.781040] controller systemd[1]: Finished Reconfigure WireGuard peers from data-mesher.
peer1: (finished: waiting for success: test -f /var/lib/data-mesher/files/home/dm_wg_star_wg_star/controller, in 5.05 seconds)
controller: waiting for success: ls /var/lib/data-mesher/files/home/dm_wg_star_wg_star/ | grep -v controller | grep -q .
controller: (finished: waiting for success: ls /var/lib/data-mesher/files/home/dm_wg_star_wg_star/ | grep -v controller | grep -q ., in 0.01 seconds)
controller: waiting for success: wg show wg-star peers | grep -q .
controller: (finished: waiting for success: wg show wg-star peers | grep -q ., in 0.02 seconds)
peer1: waiting for success: wg show wg-star peers | grep -q .
peer1: (finished: waiting for success: wg show wg-star peers | grep -q ., in 0.01 seconds)
peer1: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::8347:d476:2a4b:65b7
peer1: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::8347:d476:2a4b:65b7, in 0.01 seconds)
controller: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::35fa:0039:d6ca:cb57
controller: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::35fa:0039:d6ca:cb57, in 0.01 seconds)
controller: must succeed: wg show wg-star peers | wc -l
controller: (finished: must succeed: wg show wg-star peers | wc -l, in 0.01 seconds)
peer2: systemd-nspawn running (pid 779)
peer2: Waiting for journal at /build/vm-state-peer2/var/log/journal...
peer2: waiting for unit data-mesher.service
nixos-nspawn(peer2): TAP vde-tap1 not found; container will be isolated from VDE
nixos-nspawn(peer2): 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.
░ Spawning container peer2 on /build/vm-state-peer2.
peer2 # No journal files were found.
peer2 # No journal boot entry found for the specified boot (+0).
peer2 # [7504958.123811] peer2 systemd-journald[95]: Journal started
peer2 # [7504958.123867] peer2 systemd-journald[95]: Runtime Journal (/run/log/journal/9ca6bece9d364762b8f38b9b60384b5f) is 8M, max 2.5G, 2.4G free.
peer2 # [7504958.127984] peer2 systemd[1]: Starting Flush Journal to Persistent Storage...
peer2 # [7504958.128736] peer2 systemd[1]: Starting Network Name Resolution...
peer2 # [7504958.129364] peer2 systemd[1]: Starting Create Static Device Nodes in /dev...
peer2 # [7504958.138113] peer2 systemd-journald[95]: Time spent on flushing to /var/log/journal/9ca6bece9d364762b8f38b9b60384b5f is 1.553ms for 5 entries.
peer2 # [7504958.138113] peer2 systemd-journald[95]: System Journal (/var/log/journal/9ca6bece9d364762b8f38b9b60384b5f) is 8M, max 4G, 3.9G free.
peer2 # [7504958.144647] peer2 systemd[1]: Finished Create Static Device Nodes in /dev.
peer2 # [7504958.144859] peer2 systemd[1]: Reached target Preparation for Local File Systems.
peer2 # [7504958.144941] peer2 systemd[1]: Reached target Local File Systems.
peer2 # [7504958.145640] peer2 systemd[1]: Listening on Boot Loader Control Service Socket.
peer2 # [7504958.145684] peer2 systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container
peer2 # [7504958.146531] peer2 systemd[1]: Starting Save Transient machine-id to Disk...
peer2 # [7504958.146561] peer2 systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys
peer2 # [7504958.158467] peer2 systemd[1]: Finished Flush Journal to Persistent Storage.
peer2 # [7504958.159992] peer2 systemd[1]: Starting Create System Files and Directories...
peer2 # [7504958.176940] peer2 systemd-tmpfiles[140]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted
peer2 # [7504958.177145] peer2 systemd-tmpfiles[140]: fchmod() of /var/log/journal failed: Operation not permitted
peer2 # [7504958.177291] peer2 systemd-tmpfiles[140]: fchmod() of /var/log/journal/9ca6bece9d364762b8f38b9b60384b5f failed: Operation not permitted
peer2 # [7504958.177510] peer2 systemd-tmpfiles[140]: fchmod() of /run/log/journal failed: Operation not permitted
peer2 # [7504958.178786] peer2 systemd[1]: Finished Create System Files and Directories.
peer2 # [7504958.179832] peer2 systemd[1]: Starting Rebuild Journal Catalog...
peer2 # [7504958.180629] peer2 systemd[1]: Starting Record System Boot/Shutdown in UTMP...
peer2 # [7504958.194875] peer2 systemd[1]: Finished Record System Boot/Shutdown in UTMP.
peer2 # [7504958.203871] peer2 systemd[1]: Finished Rebuild Journal Catalog.
peer2 # [7504958.205325] peer2 systemd[1]: Starting Update is Completed...
peer2 # [7504958.218157] peer2 systemd[1]: Finished Update is Completed.
peer2 # [7504958.284626] peer2 systemd[1]: Finished Firewall.
peer2 # [7504958.285020] peer2 systemd[1]: Reached target Preparation for Network.
peer2 # [7504958.285277] peer2 systemd[1]: Listening on Network Management Resolve Hook Socket.
peer2 # [7504958.286513] peer2 systemd[1]: Starting Network Management...
peer2 # [7504958.483874] peer2 systemd[1]: Finished Save Transient machine-id to Disk.
peer2 # [7504958.691532] peer2 systemd-networkd[212]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted
peer2 # [7504958.691620] peer2 systemd-networkd[212]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted
peer2 # [7504958.698842] peer2 systemd-networkd[212]: /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.
peer2 # [7504958.699003] peer2 systemd-networkd[212]: /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.
peer2 # [7504958.699143] peer2 systemd-networkd[212]: lo: Link UP
peer2 # [7504958.699148] peer2 systemd-networkd[212]: lo: Gained carrier
peer2 # [7504958.699326] peer2 systemd-networkd[212]: eth1: Configuring with /etc/systemd/network/40-eth1.network.
peer2 # [7504958.699747] peer2 systemd[1]: Started Network Management.
peer2 # [7504958.701555] peer2 systemd-networkd[212]: wg-star: Configuring with /etc/systemd/network/40-wg-star.network.
peer2 # [7504958.701826] peer2 systemd[1]: Starting Enable Persistent Storage in systemd-networkd...
peer2 # [7504958.701860] peer2 systemd-networkd[212]: wg-star: netdev ready
peer2 # [7504958.702233] peer2 systemd-networkd[212]: eth1: Link UP
peer2 # [7504958.702441] peer2 systemd-networkd[212]: eth1: Gained carrier
peer2 # [7504958.740796] peer2 systemd-networkd[212]: wg-star: Link UP
peer2 # [7504958.740802] peer2 systemd-networkd[212]: wg-star: Gained carrier
peer2 # [7504958.750491] peer2 systemd-resolved[116]: Positive Trust Anchors:
peer2 # [7504958.750506] peer2 systemd-resolved[116]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
peer2 # [7504958.750508] peer2 systemd-resolved[116]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16
peer2 # [7504958.750544] peer2 systemd-resolved[116]: 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
peer2 # [7504958.753320] peer2 systemd[1]: Finished Enable Persistent Storage in systemd-networkd.
peer2 # [7504958.772199] peer2 systemd-resolved[116]: Using system hostname 'peer2'.
peer2 # [7504958.773756] peer2 systemd[1]: Started Network Name Resolution.
peer2 # [7504958.773891] peer2 systemd[1]: Reached target Network.
peer2 # [7504958.774004] peer2 systemd[1]: Reached target System Initialization.
peer2 # [7504958.774173] peer2 systemd[1]: Started Watch for WireGuard controller info from data-mesher.
peer2 # [7504958.774232] peer2 systemd[1]: Started Periodic heartbeat re-publish for dm-wireguard-star peer.
peer2 # [7504958.774301] peer2 systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container
peer2 # [7504958.774342] peer2 systemd[1]: Started Daily Cleanup of Temporary Directories.
peer2 # [7504958.774384] peer2 systemd[1]: Reached target Path Units.
peer2 # [7504958.774457] peer2 systemd[1]: Reached target Timer Units.
peer2 # [7504958.774677] peer2 systemd[1]: Listening on D-Bus System Message Bus Socket.
peer2 # [7504958.774880] peer2 systemd[1]: Listening on Nix Daemon Socket.
peer2 # [7504958.775095] peer2 systemd[1]: Listening on Virtual Machine and Container Registration Service Socket.
peer2 # [7504958.775153] peer2 systemd[1]: Reached target Socket Units.
peer2 # [7504958.775229] peer2 systemd[1]: Reached target Basic System.
peer2 # [7504958.777255] peer2 systemd[1]: Starting data mesher daemon...
peer2 # [7504958.778564] peer2 systemd[1]: Starting Import lastlog data into lastlog2 database...
peer2 # [7504958.779929] peer2 systemd[1]: Starting Name Service Cache Daemon (nsncd)...
peer2 # [7504958.782123] peer2 systemd[1]: Starting D-Bus System Message Bus...
peer2 # [7504958.829884] peer2 systemd[1]: Finished Import lastlog data into lastlog2 database.
peer2 # [7504958.919012] peer2 nsncd[220]: Sep 03 20:06:24.972 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
peer2 # [7504958.919101] peer2 systemd[1]: Started Name Service Cache Daemon (nsncd).
peer2 # [7504958.919194] peer2 systemd[1]: Reached target Host and Network Name Lookups.
peer2 # [7504958.919302] peer2 systemd[1]: Reached target User and Group Name Lookups.
peer2 # [7504958.921208] peer2 systemd[1]: Starting User Login Management...
peer2 # [7504958.922543] peer2 systemd[1]: Starting Permit User Sessions...
peer2 # [7504958.960028] peer2 systemd[1]: Finished Permit User Sessions.
peer2 # [7504958.961566] peer2 systemd[1]: Started Console Getty.
peer2 # [7504958.961645] peer2 systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0
peer2 # [7504958.961687] peer2 systemd[1]: Reached target Login Prompts.
peer2 # [7504958.993858] peer2 dbus-broker-launch[221]: Looking up NSS user entry for 'systemd-timesync'...
peer2 # [7504958.995206] peer2 dbus-broker-launch[221]: NSS returned no entry for 'systemd-timesync'
peer2 # [7504958.995206] peer2 dbus-broker-launch[221]: Invalid user-name in /nix/store/xsr87dgy2kj3mg3fn4f91cnqa6qwvd21-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync"
peer2 # [7504958.995669] peer2 systemd[1]: Started D-Bus System Message Bus.
peer2 # [7504959.004720] peer2 dbus-broker-launch[221]: Ready
peer2 # [7504959.115282] peer2 systemd[1]: etc-machine\x2did.mount: Deactivated successfully.
peer2 # [7504959.248893] peer2 data-mesher[218]: time=2026-09-03T20:06:25.301Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo]
peer2 # [7504959.249936] peer2 data-mesher[218]: time=2026-09-03T20:06:25.303Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466: [/dns/controller.clan/tcp/7946]} {12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2: [/dns/peer1.clan/tcp/7946]} {12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt: [/dns/peer2.clan/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
peer2 # [7504959.249936] peer2 data-mesher[218]: time=2026-09-03T20:06:25.303Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml
peer2 # [7504959.261787] peer2 data-mesher[218]: time=2026-09-03T20:06:25.314Z level=INFO msg="checking file integrity"
peer2 # [7504959.261900] peer2 data-mesher[218]: time=2026-09-03T20:06:25.315Z level=INFO msg="file integrity check complete"
peer2 # [7504959.266328] peer2 data-mesher[218]: time=2026-09-03T20:06:25.319Z level=INFO msg="libp2p host created" peer_id=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt addresses="[/ip4/127.0.0.1/tcp/7946 /ip4/192.168.1.3/tcp/7946 /ip6/::1/tcp/7946 /ip6/2001:db8:1::3/tcp/7946 /ip6/fda1:5c8::3e0:aacd:42ac:6269/tcp/7946]"
peer2 # [7504959.266430] peer2 data-mesher[218]: time=2026-09-03T20:06:25.319Z level=INFO msg="registered HTTP route" method=GET path=/files
peer2 # [7504959.266430] peer2 data-mesher[218]: time=2026-09-03T20:06:25.319Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name
peer2 # [7504959.266430] peer2 data-mesher[218]: time=2026-09-03T20:06:25.319Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name
peer2 # [7504959.266430] peer2 data-mesher[218]: time=2026-09-03T20:06:25.319Z level=INFO msg="starting server"
peer2 # [7504959.266649] peer2 data-mesher[218]: time=2026-09-03T20:06:25.319Z level=INFO msg="waiting for DHT to populate" delay=10s
peer2 # [7504959.266649] peer2 data-mesher[218]: time=2026-09-03T20:06:25.319Z level=INFO msg="HTTP server listening" address=[::1]:7331
peer2 # [7504959.266649] peer2 data-mesher[218]: time=2026-09-03T20:06:25.319Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331
peer2 # [7504959.273605] peer2 data-mesher[218]: time=2026-09-03T20:06:25.326Z level=INFO msg="peer connected" peer_id=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 remote_addr=/ip4/192.168.1.1/tcp/7946
peer2 # [7504959.281864] peer2 data-mesher[218]: time=2026-09-03T20:06:25.335Z level=INFO msg="peer connected" peer_id=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 remote_addr=/ip4/192.168.1.2/tcp/7946
peer2 # [7504959.452181] peer2 systemd-logind[238]: New seat seat0.
peer2 # [7504959.452408] peer2 systemd[1]: Started User Login Management.
peer2 # [7504959.453631] peer2 systemd[1]: Starting linger-users.service...
controller # [7504959.275295] controller data-mesher[230]: time=2026-09-03T20:06:25.328Z level=INFO msg="peer connected" peer_id=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt remote_addr=/ip4/192.168.1.3/tcp/7946
peer1 # [7504959.283720] peer1 data-mesher[218]: time=2026-09-03T20:06:25.336Z level=INFO msg="peer connected" peer_id=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt remote_addr=/ip4/192.168.1.3/tcp/7946
peer2 # [7504959.513936] peer2 systemd[1]: linger-users.service: Deactivated successfully.
peer2 # [7504959.514128] peer2 systemd[1]: Finished linger-users.service.
peer2 # [7504960.576118] peer2 systemd-networkd[212]: eth1: Gained IPv6LL
peer1 # [7504961.612555] peer1 data-mesher[218]: time=2026-09-03T20:06:27.665Z level=DEBUG msg="attempting push/pull" peer_count=1
peer1 # [7504961.612555] peer1 data-mesher[218]: time=2026-09-03T20:06:27.665Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504961.613777] peer1 data-mesher[218]: time=2026-09-03T20:06:27.666Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504961.614113] peer1 data-mesher[218]: time=2026-09-03T20:06:27.667Z level=INFO msg="state exchange complete" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504961.614179] peer1 data-mesher[218]: time=2026-09-03T20:06:27.667Z level=DEBUG msg="push/pull successful" interval=5s
peer2 # [7504961.612957] peer2 data-mesher[218]: time=2026-09-03T20:06:27.666Z level=INFO msg="received state sync from peer" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer2 # [7504961.612957] peer2 data-mesher[218]: time=2026-09-03T20:06:27.666Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer2 # [7504961.613392] peer2 data-mesher[218]: time=2026-09-03T20:06:27.666Z level=DEBUG msg="new file detected" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 name=dm_wg_star_wg_star/controller name=dm_wg_star_wg_star/controller
peer2 # [7504961.613392] peer2 data-mesher[218]: time=2026-09-03T20:06:27.666Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/controller
peer2 # [7504961.613392] peer2 data-mesher[218]: time=2026-09-03T20:06:27.666Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/controller signed_at="2026-09-03 20:06:17.734 +0000 UTC" signed_by="nPzNL9EwkbvuZIKP5H2nx8SyUYpgCLnMm1a4dWKOCpQ=" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer2 # [7504961.613735] peer2 data-mesher[218]: time=2026-09-03T20:06:27.666Z level=DEBUG msg="new file detected" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 name=dm_wg_star_wg_star/controller name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk
peer2 # [7504961.613853] peer2 data-mesher[218]: time=2026-09-03T20:06:27.667Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk
peer2 # [7504961.613942] peer2 data-mesher[218]: time=2026-09-03T20:06:27.667Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk signed_at="2026-09-03 20:06:17.822 +0000 UTC" signed_by="mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk=" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer2 # [7504961.621058] peer2 systemd[1]: Starting Reconfigure WireGuard with controller from data-mesher...
peer2 # [7504961.624934] peer2 data-mesher[218]: time=2026-09-03T20:06:27.678Z level=INFO msg="download complete" name=dm_wg_star_wg_star/controller signed_at="2026-09-03 20:06:17.734 +0000 UTC" signed_by="nPzNL9EwkbvuZIKP5H2nx8SyUYpgCLnMm1a4dWKOCpQ=" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 written=true elapsed=11.747716ms
peer2 # [7504961.626059] peer2 data-mesher[218]: time=2026-09-03T20:06:27.679Z level=INFO msg="download complete" name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk signed_at="2026-09-03 20:06:17.822 +0000 UTC" signed_by="mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk=" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 written=true elapsed=12.169322ms
peer2 # [7504961.775942] peer2 systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully.
peer2 # [7504961.776294] peer2 systemd[1]: Finished Reconfigure WireGuard with controller from data-mesher.
controller # [7504961.611920] controller data-mesher[230]: time=2026-09-03T20:06:27.665Z level=DEBUG msg="attempting push/pull" peer_count=1
controller # [7504961.612633] controller data-mesher[230]: time=2026-09-03T20:06:27.665Z level=DEBUG msg="initiating state exchange" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt timeout=5s
controller # [7504961.613180] controller data-mesher[230]: time=2026-09-03T20:06:27.666Z level=INFO msg="received state sync from peer" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504961.613180] controller data-mesher[230]: time=2026-09-03T20:06:27.666Z level=INFO msg="merging remote state" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504961.613748] controller data-mesher[230]: time=2026-09-03T20:06:27.666Z level=INFO msg="received file request" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/controller
controller # [7504961.613967] controller data-mesher[230]: time=2026-09-03T20:06:27.667Z level=INFO msg="merging remote state" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
controller # [7504961.613967] controller data-mesher[230]: time=2026-09-03T20:06:27.667Z level=INFO msg="state exchange complete" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt timeout=5s
controller # [7504961.614076] controller data-mesher[230]: time=2026-09-03T20:06:27.667Z level=DEBUG msg="push/pull successful" interval=5s
controller # [7504961.615091] controller data-mesher[230]: time=2026-09-03T20:06:27.668Z level=INFO msg="received file request" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk
controller # [7504961.615155] controller data-mesher[230]: time=2026-09-03T20:06:27.668Z level=INFO msg="file transfer complete" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/controller
controller # [7504961.616477] controller data-mesher[230]: time=2026-09-03T20:06:27.669Z level=INFO msg="file transfer complete" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/mdTGU1yKJUwSmz7kSG3JBNtPNRJZpxAbjdfYYFi0VZk
peer1 # [7504966.614593] peer1 data-mesher[218]: time=2026-09-03T20:06:32.667Z level=DEBUG msg="attempting push/pull" peer_count=1
peer1 # [7504966.614593] peer1 data-mesher[218]: time=2026-09-03T20:06:32.667Z level=DEBUG msg="initiating state exchange" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt timeout=5s
peer1 # [7504966.616610] peer1 data-mesher[218]: time=2026-09-03T20:06:32.669Z level=INFO msg="merging remote state" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
peer1 # [7504966.617195] peer1 data-mesher[218]: time=2026-09-03T20:06:32.670Z level=INFO msg="state exchange complete" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt timeout=5s
peer1 # [7504966.617276] peer1 data-mesher[218]: time=2026-09-03T20:06:32.670Z level=DEBUG msg="push/pull successful" interval=5s
peer2 # [7504966.616021] peer2 data-mesher[218]: time=2026-09-03T20:06:32.669Z level=INFO msg="received state sync from peer" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
peer2 # [7504966.616021] peer2 data-mesher[218]: time=2026-09-03T20:06:32.669Z level=INFO msg="merging remote state" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
peer2 # [7504966.616768] peer2 data-mesher[218]: time=2026-09-03T20:06:32.669Z level=INFO msg="received state sync from peer" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer2 # [7504966.616768] peer2 data-mesher[218]: time=2026-09-03T20:06:32.669Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
controller # [7504966.614567] controller data-mesher[230]: time=2026-09-03T20:06:32.667Z level=DEBUG msg="attempting push/pull" peer_count=1
controller # [7504966.615308] controller data-mesher[230]: time=2026-09-03T20:06:32.667Z level=DEBUG msg="initiating state exchange" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt timeout=5s
controller # [7504966.617027] controller data-mesher[230]: time=2026-09-03T20:06:32.670Z level=INFO msg="merging remote state" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
controller # [7504966.617295] controller data-mesher[230]: time=2026-09-03T20:06:32.670Z level=INFO msg="state exchange complete" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt timeout=5s
controller # [7504966.617370] controller data-mesher[230]: time=2026-09-03T20:06:32.670Z level=DEBUG msg="push/pull successful" interval=5s
peer2: still waiting for container 'peer2' to reach ready state...
peer2 # [7504969.267470] peer2 data-mesher[218]: time=2026-09-03T20:06:35.320Z level=INFO msg="performing state exchange with peers on join" count=1
peer2 # [7504969.267470] peer2 data-mesher[218]: time=2026-09-03T20:06:35.320Z level=DEBUG msg="initiating state exchange" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 timeout=5s
peer2 # [7504969.268458] peer2 data-mesher[218]: time=2026-09-03T20:06:35.321Z level=INFO msg="merging remote state" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
peer2 # [7504969.268682] peer2 data-mesher[218]: time=2026-09-03T20:06:35.321Z level=INFO msg="state exchange complete" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 timeout=5s
peer2 # [7504969.268711] peer2 data-mesher[218]: time=2026-09-03T20:06:35.321Z level=INFO msg="server started"
peer2 # [7504969.268806] peer2 data-mesher[218]: time=2026-09-03T20:06:35.321Z level=INFO msg="starting expired-file sweeper" interval=1m0s
peer2 # [7504969.269021] peer2 systemd[1]: Started data mesher daemon.
peer2 # [7504969.270263] peer2 systemd[1]: Starting Publish WireGuard peer info to data-mesher...
peer2 # [7504969.438000] peer2 systemd[1]: Starting Reconfigure WireGuard with controller from data-mesher...
peer2 # [7504969.439886] peer2 data-mesher[218]: time=2026-09-03T20:06:35.492Z level=INFO msg=http_request uri=/files/dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck status=204
peer2 # [7504969.440049] peer2 dm-wg-star-publish[295]: Status: 204 No Content
peer2 # [7504969.442870] peer2 systemd[1]: dm-wg-star-wg-star-publish.service: Deactivated successfully.
peer2 # [7504969.480331] peer2 systemd[1]: Finished Publish WireGuard peer info to data-mesher.
peer2 # [7504969.480942] peer2 systemd[1]: Reached target Multi-User System.
peer2 # [7504969.577916] peer2 systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully.
peer1 # [7504969.268056] peer1 data-mesher[218]: time=2026-09-03T20:06:35.321Z level=INFO msg="received state sync from peer" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
peer1 # [7504969.268056] peer1 data-mesher[218]: time=2026-09-03T20:06:35.321Z level=INFO msg="merging remote state" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
peer2: (finished: waiting for unit data-mesher.service, in 12.66 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
controller: waiting for success: test $(ls /var/lib/data-mesher/files/home/dm_wg_star_wg_star/ | grep -v controller | wc -l) -gt 1
??? 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
peer2 # [7504969.578120] peer2 systemd[1]: Finished Reconfigure WireGuard with controller from data-mesher.
peer2 # [7504969.580744] peer2 systemd[1]: Startup finished in 11.911s.
peer1 # [7504971.617975] peer1 data-mesher[218]: time=2026-09-03T20:06:37.671Z level=DEBUG msg="attempting push/pull" peer_count=1
peer1 # [7504971.617975] peer1 data-mesher[218]: time=2026-09-03T20:06:37.671Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504971.618797] peer1 data-mesher[218]: time=2026-09-03T20:06:37.671Z level=INFO msg="received state sync from peer" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504971.618797] peer1 data-mesher[218]: time=2026-09-03T20:06:37.671Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504971.619566] peer1 data-mesher[218]: time=2026-09-03T20:06:37.672Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504971.620163] peer1 data-mesher[218]: time=2026-09-03T20:06:37.673Z level=INFO msg="state exchange complete" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504971.620229] peer1 data-mesher[218]: time=2026-09-03T20:06:37.673Z level=DEBUG msg="push/pull successful" interval=5s
controller # [7504971.618027] controller data-mesher[230]: time=2026-09-03T20:06:37.671Z level=DEBUG msg="attempting push/pull" peer_count=1
controller # [7504971.618027] controller data-mesher[230]: time=2026-09-03T20:06:37.671Z level=DEBUG msg="initiating state exchange" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 timeout=5s
controller # [7504971.618797] controller data-mesher[230]: time=2026-09-03T20:06:37.671Z level=INFO msg="received state sync from peer" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504971.618797] controller data-mesher[230]: time=2026-09-03T20:06:37.671Z level=INFO msg="merging remote state" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504971.619481] controller data-mesher[230]: time=2026-09-03T20:06:37.672Z level=INFO msg="merging remote state" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504971.619684] controller data-mesher[230]: time=2026-09-03T20:06:37.672Z level=INFO msg="state exchange complete" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 timeout=5s
controller # [7504971.619750] controller data-mesher[230]: time=2026-09-03T20:06:37.672Z level=DEBUG msg="push/pull successful" interval=5s
peer1 # [7504974.269833] peer1 data-mesher[218]: time=2026-09-03T20:06:40.322Z level=INFO msg="received state sync from peer" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
peer1 # [7504974.269833] peer1 data-mesher[218]: time=2026-09-03T20:06:40.322Z level=INFO msg="merging remote state" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
peer1 # [7504974.270560] peer1 data-mesher[218]: time=2026-09-03T20:06:40.323Z level=DEBUG msg="new file detected" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck
peer1 # [7504974.270621] peer1 data-mesher[218]: time=2026-09-03T20:06:40.323Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck
peer1 # [7504974.270701] peer1 data-mesher[218]: time=2026-09-03T20:06:40.323Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck signed_at="2026-09-03 20:06:35.487 +0000 UTC" signed_by="EYubHgwK6l7uZn6VR692j3+CBBOiQOM/6G2/YIHkhck=" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
peer1 # [7504974.279173] peer1 systemd[1]: Starting Reconfigure WireGuard with controller from data-mesher...
peer1 # [7504974.445065] peer1 systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully.
peer1 # [7504974.445325] peer1 systemd[1]: Finished Reconfigure WireGuard with controller from data-mesher.
peer1 # [7504974.621859] peer1 data-mesher[218]: time=2026-09-03T20:06:40.674Z level=INFO msg="download complete" name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck signed_at="2026-09-03 20:06:35.487 +0000 UTC" signed_by="EYubHgwK6l7uZn6VR692j3+CBBOiQOM/6G2/YIHkhck=" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt written=true elapsed=351.067753ms
peer2 # [7504974.269040] peer2 data-mesher[218]: time=2026-09-03T20:06:40.322Z level=DEBUG msg="attempting push/pull" peer_count=2
peer2 # [7504974.269040] peer2 data-mesher[218]: time=2026-09-03T20:06:40.322Z level=DEBUG msg="initiating state exchange" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 timeout=5s
peer2 # [7504974.271265] peer2 data-mesher[218]: time=2026-09-03T20:06:40.324Z level=INFO msg="received file request" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck
peer2 # [7504974.271412] peer2 data-mesher[218]: time=2026-09-03T20:06:40.324Z level=INFO msg="merging remote state" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
peer2 # [7504974.273696] peer2 data-mesher[218]: time=2026-09-03T20:06:40.325Z level=INFO msg="state exchange complete" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 timeout=5s
peer2 # [7504974.273804] peer2 data-mesher[218]: time=2026-09-03T20:06:40.326Z level=DEBUG msg="push/pull successful" interval=5s
peer2 # [7504974.273857] peer2 data-mesher[218]: time=2026-09-03T20:06:40.326Z level=INFO msg="file transfer complete" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck
controller: (finished: waiting for success: test $(ls /var/lib/data-mesher/files/home/dm_wg_star_wg_star/ | grep -v controller | wc -l) -gt 1, in 7.09 seconds)
controller: waiting for success: test $(wg show wg-star peers | wc -l) -gt 1
controller: (finished: waiting for success: test $(wg show wg-star peers | wc -l) -gt 1, in 0.01 seconds)
peer2: waiting for success: wg show wg-star peers | grep -q .
peer1 # [7504976.620757] peer1 data-mesher[218]: time=2026-09-03T20:06:42.673Z level=DEBUG msg="attempting push/pull" peer_count=1
peer1 # [7504976.620757] peer1 data-mesher[218]: time=2026-09-03T20:06:42.673Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504976.623194] peer1 data-mesher[218]: time=2026-09-03T20:06:42.675Z level=INFO msg="received file request" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck
peer1 # [7504976.623194] peer1 data-mesher[218]: time=2026-09-03T20:06:42.675Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504976.623469] peer1 data-mesher[218]: time=2026-09-03T20:06:42.676Z level=INFO msg="state exchange complete" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504976.624138] peer1 data-mesher[218]: time=2026-09-03T20:06:42.676Z level=DEBUG msg="push/pull successful" interval=5s
peer1 # [7504976.626741] peer1 data-mesher[218]: time=2026-09-03T20:06:42.679Z level=INFO msg="file transfer complete" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 network="vsQC5anPX1PCAwBi4nNaJMbp8YEmqnn4tKUlmVf0Jnk=" name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck
peer2: (finished: waiting for success: wg show wg-star peers | grep -q ., in 0.01 seconds)
peer2: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::8347:d476:2a4b:65b7
peer2 # [7504976.621541] peer2 data-mesher[218]: time=2026-09-03T20:06:42.674Z level=INFO msg="received state sync from peer" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer2 # [7504976.621541] peer2 data-mesher[218]: time=2026-09-03T20:06:42.674Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
controller # [7504976.620952] controller data-mesher[230]: time=2026-09-03T20:06:42.673Z level=DEBUG msg="attempting push/pull" peer_count=1
controller # [7504976.620952] controller data-mesher[230]: time=2026-09-03T20:06:42.673Z level=DEBUG msg="initiating state exchange" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt timeout=5s
controller # [7504976.621764] controller data-mesher[230]: time=2026-09-03T20:06:42.674Z level=INFO msg="received state sync from peer" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504976.621764] controller data-mesher[230]: time=2026-09-03T20:06:42.674Z level=INFO msg="merging remote state" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504976.621965] controller data-mesher[230]: time=2026-09-03T20:06:42.675Z level=DEBUG msg="new file detected" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck
controller # [7504976.623418] controller data-mesher[230]: time=2026-09-03T20:06:42.675Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck
controller # [7504976.623418] controller data-mesher[230]: time=2026-09-03T20:06:42.675Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck signed_at="2026-09-03 20:06:35.487 +0000 UTC" signed_by="EYubHgwK6l7uZn6VR692j3+CBBOiQOM/6G2/YIHkhck=" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2
controller # [7504976.623418] controller data-mesher[230]: time=2026-09-03T20:06:42.675Z level=INFO msg="merging remote state" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
controller # [7504976.623418] controller data-mesher[230]: time=2026-09-03T20:06:42.676Z level=DEBUG msg="new file detected" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck
controller # [7504976.625356] controller data-mesher[230]: time=2026-09-03T20:06:42.676Z level=INFO msg="state exchange complete" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt timeout=5s
controller # [7504976.625356] controller data-mesher[230]: time=2026-09-03T20:06:42.676Z level=DEBUG msg="push/pull successful" interval=5s
controller # [7504976.632294] controller systemd[1]: Starting Reconfigure WireGuard peers from data-mesher...
controller # [7504976.735727] controller data-mesher[230]: time=2026-09-03T20:06:42.788Z level=INFO msg="download complete" name=dm_wg_star_wg_star/EYubHgwK6l7uZn6VR692j3-CBBOiQOM_6G2_YIHkhck signed_at="2026-09-03 20:06:35.487 +0000 UTC" signed_by="EYubHgwK6l7uZn6VR692j3+CBBOiQOM/6G2/YIHkhck=" peer=12D3KooWLArj3AqHk9brvghuD9LLyzDkq72Pt4kUoWyY3bLwFLP2 written=true elapsed=113.583793ms
controller # [7504976.859903] controller systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully.
controller # [7504976.860166] controller systemd[1]: Finished Reconfigure WireGuard peers from data-mesher.
peer2: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::8347:d476:2a4b:65b7, in 1.00 seconds)
controller: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::03e0:aacd:42ac:6269
controller: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::03e0:aacd:42ac:6269, in 0.01 seconds)
peer1: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::03e0:aacd:42ac:6269
peer1: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::03e0:aacd:42ac:6269, in 0.01 seconds)
peer2: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::35fa:0039:d6ca:cb57
peer2: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::35fa:0039:d6ca:cb57, in 0.01 seconds)
(finished: run the VM test script, in 38.63 seconds)
controller # [7504979.274779] controller data-mesher[230]: time=2026-09-03T20:06:45.327Z level=INFO msg="received state sync from peer" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
controller # [7504979.274779] controller data-mesher[230]: time=2026-09-03T20:06:45.327Z level=INFO msg="merging remote state" peer=12D3KooWAzrZtYMgQL5qJux2QuuLVaJNEv7Hf1SizQKM7fbzWxvt
peer2 # [7504979.274065] peer2 data-mesher[218]: time=2026-09-03T20:06:45.327Z level=DEBUG msg="attempting push/pull" peer_count=2
peer2 # [7504979.274805] peer2 data-mesher[218]: time=2026-09-03T20:06:45.327Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer2 # [7504979.275869] peer2 data-mesher[218]: time=2026-09-03T20:06:45.329Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer2 # [7504979.277039] peer2 data-mesher[218]: time=2026-09-03T20:06:45.330Z level=INFO msg="state exchange complete" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer2 # [7504979.277100] peer2 data-mesher[218]: time=2026-09-03T20:06:45.330Z level=DEBUG msg="push/pull successful" interval=5s
test script finished in 42.44s
cleanup
kill NspawnMachine (pid 50)
peer1 # [7504981.623804] peer1 data-mesher[218]: time=2026-09-03T20:06:47.676Z level=DEBUG msg="attempting push/pull" peer_count=1
peer1 # [7504981.624705] peer1 data-mesher[218]: time=2026-09-03T20:06:47.677Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504981.626265] peer1 data-mesher[218]: time=2026-09-03T20:06:47.679Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer1 # [7504981.627412] peer1 data-mesher[218]: time=2026-09-03T20:06:47.680Z level=INFO msg="state exchange complete" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466 timeout=5s
peer1 # [7504981.627483] peer1 data-mesher[218]: time=2026-09-03T20:06:47.680Z level=DEBUG msg="push/pull successful" interval=5s
peer2 # [7504981.625063] peer2 data-mesher[218]: time=2026-09-03T20:06:47.678Z level=INFO msg="received state sync from peer" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
peer2 # [7504981.625385] peer2 data-mesher[218]: time=2026-09-03T20:06:47.678Z level=INFO msg="merging remote state" peer=12D3KooWFrNBKcZwfMwxD3rbRQ5DeByJLixD9xMKNUzgN7ZiA466
kill NspawnMachine (pid 53)
Container controller terminated by signal KILL.
kill NspawnMachine (pid 779)
Container peer1 terminated by signal KILL.
Container peer2 terminated by signal KILL.
(finished: cleanup, in 0.84 seconds)