build01: building hr9vdygkx02gpy1ll6k0avdza0sr5xf3-container-test-run-dm-wireguard-star.drv 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 # [297744.468607] controller systemd-journald[107]: Journal started controller # [297744.468668] controller systemd-journald[107]: Runtime Journal (/run/log/journal/ab053c6ccb4c4e9f99db0ca50d6008d2) is 8M, max 2.5G, 2.4G free. controller # [297744.473351] controller systemd[1]: Finished Apply Kernel Variables. controller # [297744.486173] controller systemd[1]: Finished Create Static Device Nodes in /dev gracefully. controller # [297744.499559] controller systemd[1]: Starting Flush Journal to Persistent Storage... controller # [297744.500444] controller systemd[1]: Starting Network Name Resolution... controller # [297744.501211] controller systemd[1]: Starting Create Static Device Nodes in /dev... controller # [297744.510613] controller systemd-journald[107]: Time spent on flushing to /var/log/journal/ab053c6ccb4c4e9f99db0ca50d6008d2 is 1.796ms for 7 entries. controller # [297744.510613] controller systemd-journald[107]: System Journal (/var/log/journal/ab053c6ccb4c4e9f99db0ca50d6008d2) is 8M, max 4G, 3.9G free. controller # [297744.527029] controller systemd[1]: Finished Create Static Device Nodes in /dev. controller # [297744.527698] controller systemd[1]: Reached target Preparation for Local File Systems. controller # [297744.527830] controller systemd[1]: Reached target Local File Systems. controller # [297744.528756] controller systemd[1]: Listening on Boot Loader Control Service Socket. controller # [297744.528809] controller systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container controller # [297744.529699] controller systemd[1]: Starting Save Transient machine-id to Disk... controller # [297744.529738] controller systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys controller # [297744.540107] controller systemd[1]: Finished Flush Journal to Persistent Storage. controller # [297744.541458] controller systemd[1]: Starting Create System Files and Directories... controller # [297744.557722] controller systemd-tmpfiles[166]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted controller # [297744.557907] controller systemd-tmpfiles[166]: fchmod() of /var/log/journal failed: Operation not permitted controller # [297744.558040] controller systemd-tmpfiles[166]: fchmod() of /var/log/journal/ab053c6ccb4c4e9f99db0ca50d6008d2 failed: Operation not permitted controller # [297744.558235] controller systemd-tmpfiles[166]: fchmod() of /run/log/journal failed: Operation not permitted controller # [297744.559614] controller systemd[1]: Finished Create System Files and Directories. controller # [297744.560631] controller systemd[1]: Starting Rebuild Journal Catalog... controller # [297744.561318] controller systemd[1]: Starting Record System Boot/Shutdown in UTMP... controller # [297744.574878] controller systemd[1]: Finished Record System Boot/Shutdown in UTMP. controller # [297744.582901] controller systemd[1]: Finished Rebuild Journal Catalog. controller # [297744.584041] controller systemd[1]: Starting Update is Completed... controller # [297744.594975] controller systemd[1]: Finished Update is Completed. controller # [297744.688289] controller systemd[1]: Finished Firewall. controller # [297744.688480] controller systemd[1]: Reached target Preparation for Network. controller # [297744.688732] controller systemd[1]: Listening on Network Management Resolve Hook Socket. controller # [297744.689826] controller systemd[1]: Starting Network Management... controller # [297744.967486] controller systemd[1]: Finished Save Transient machine-id to Disk. controller # [297745.289656] controller systemd-networkd[226]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted controller # [297745.289745] controller systemd-networkd[226]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted controller # [297745.300427] controller systemd-networkd[226]: /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 # [297745.300591] controller systemd-networkd[226]: /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 # [297745.300725] controller systemd-networkd[226]: lo: Link UP controller # [297745.300729] controller systemd-networkd[226]: lo: Gained carrier controller # [297745.300923] controller systemd-networkd[226]: eth1: Configuring with /etc/systemd/network/40-eth1.network. controller # [297745.301351] controller systemd[1]: Started Network Management. controller # [297745.301886] controller systemd-networkd[226]: wg-star: Configuring with /etc/systemd/network/40-wg-star.network. controller # [297745.302184] controller systemd-networkd[226]: wg-star: netdev ready controller # [297745.302551] controller systemd-networkd[226]: eth1: Link UP controller # [297745.302746] controller systemd-networkd[226]: eth1: Gained carrier controller # [297745.303014] controller systemd[1]: Starting Enable Persistent Storage in systemd-networkd... controller # [297745.345089] controller systemd-networkd[226]: wg-star: Link UP controller # [297745.345094] controller systemd-networkd[226]: wg-star: Gained carrier controller # [297745.351760] controller systemd[1]: Finished Enable Persistent Storage in systemd-networkd. peer1 # [297744.458355] peer1 systemd-journald[99]: Journal started peer1 # [297744.458417] peer1 systemd-journald[99]: Runtime Journal (/run/log/journal/66a9e35882874efbbce59ef5fc8602e5) is 8M, max 2.5G, 2.4G free. peer1 # [297744.463625] peer1 systemd[1]: Finished Apply Kernel Variables. peer1 # [297744.476432] peer1 systemd[1]: Finished Create Static Device Nodes in /dev gracefully. peer1 # [297744.489663] peer1 systemd[1]: Starting Flush Journal to Persistent Storage... peer1 # [297744.490611] peer1 systemd[1]: Starting Network Name Resolution... peer1 # [297744.491273] peer1 systemd[1]: Starting Create Static Device Nodes in /dev... peer1 # [297744.501300] peer1 systemd-journald[99]: Time spent on flushing to /var/log/journal/66a9e35882874efbbce59ef5fc8602e5 is 1.693ms for 7 entries. peer1 # [297744.501300] peer1 systemd-journald[99]: System Journal (/var/log/journal/66a9e35882874efbbce59ef5fc8602e5) is 8M, max 4G, 3.9G free. peer1 # [297744.518141] peer1 systemd[1]: Finished Create Static Device Nodes in /dev. peer1 # [297744.518783] peer1 systemd[1]: Reached target Preparation for Local File Systems. peer1 # [297744.518885] peer1 systemd[1]: Reached target Local File Systems. peer1 # [297744.519742] peer1 systemd[1]: Listening on Boot Loader Control Service Socket. peer1 # [297744.519791] peer1 systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container peer1 # [297744.520665] peer1 systemd[1]: Starting Save Transient machine-id to Disk... peer1 # [297744.520699] peer1 systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys peer1 # [297744.538899] peer1 systemd[1]: Finished Flush Journal to Persistent Storage. peer1 # [297744.540576] peer1 systemd[1]: Starting Create System Files and Directories... peer1 # [297744.555729] peer1 systemd-tmpfiles[160]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted peer1 # [297744.555879] peer1 systemd-tmpfiles[160]: fchmod() of /var/log/journal failed: Operation not permitted peer1 # [297744.555984] peer1 systemd-tmpfiles[160]: fchmod() of /var/log/journal/66a9e35882874efbbce59ef5fc8602e5 failed: Operation not permitted peer1 # [297744.556150] peer1 systemd-tmpfiles[160]: fchmod() of /run/log/journal failed: Operation not permitted peer1 # [297744.557322] peer1 systemd[1]: Finished Create System Files and Directories. peer1 # [297744.558413] peer1 systemd[1]: Starting Rebuild Journal Catalog... peer1 # [297744.559173] peer1 systemd[1]: Starting Record System Boot/Shutdown in UTMP... peer1 # [297744.574044] peer1 systemd[1]: Finished Record System Boot/Shutdown in UTMP. peer1 # [297744.582739] peer1 systemd[1]: Finished Rebuild Journal Catalog. peer1 # [297744.584113] peer1 systemd[1]: Starting Update is Completed... peer1 # [297744.594937] peer1 systemd[1]: Finished Update is Completed. peer1 # [297744.638696] peer1 systemd[1]: Finished Firewall. peer1 # [297744.638852] peer1 systemd[1]: Reached target Preparation for Network. peer1 # [297744.639079] peer1 systemd[1]: Listening on Network Management Resolve Hook Socket. peer1 # [297744.640276] peer1 systemd[1]: Starting Network Management... peer1 # [297744.966646] peer1 systemd[1]: Finished Save Transient machine-id to Disk. peer1 # [297745.305571] peer1 systemd-networkd[216]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted peer1 # [297745.305653] peer1 systemd-networkd[216]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted peer1 # [297745.315102] peer1 systemd-networkd[216]: /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 # [297745.315265] peer1 systemd-networkd[216]: /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 # [297745.315390] peer1 systemd-networkd[216]: lo: Link UP peer1 # [297745.315393] peer1 systemd-networkd[216]: lo: Gained carrier peer1 # [297745.315582] peer1 systemd-networkd[216]: eth1: Configuring with /etc/systemd/network/40-eth1.network. peer1 # [297745.315903] peer1 systemd[1]: Started Network Management. peer1 # [297745.344477] peer1 systemd[1]: Starting Enable Persistent Storage in systemd-networkd... peer1 # [297745.345042] peer1 systemd-networkd[216]: wg-star: Configuring with /etc/systemd/network/40-wg-star.network. peer1 # [297745.345340] peer1 systemd-networkd[216]: wg-star: netdev ready peer1 # [297745.345712] peer1 systemd-networkd[216]: eth1: Link UP peer1 # [297745.345911] peer1 systemd-networkd[216]: eth1: Gained carrier peer1 # [297745.376867] peer1 systemd-networkd[216]: wg-star: Link UP peer1 # [297745.376871] peer1 systemd-networkd[216]: wg-star: Gained carrier peer1 # [297745.377899] peer1 systemd[1]: Finished Enable Persistent Storage in systemd-networkd. controller # [297745.458384] controller systemd[1]: etc-machine\x2did.mount: Deactivated successfully. peer1 # [297745.453013] peer1 systemd[1]: etc-machine\x2did.mount: Deactivated successfully. peer1 # [297745.528282] peer1 systemd-resolved[131]: Positive Trust Anchors: peer1 # [297745.528295] peer1 systemd-resolved[131]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d peer1 # [297745.528300] peer1 systemd-resolved[131]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16 peer1 # [297745.528334] peer1 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 peer1 # [297745.548211] peer1 systemd-resolved[131]: Using system hostname 'peer1'. peer1 # [297745.549694] peer1 systemd[1]: Started Network Name Resolution. peer1 # [297745.549777] peer1 systemd[1]: Reached target Network. peer1 # [297745.549853] peer1 systemd[1]: Reached target System Initialization. peer1 # [297745.549950] peer1 systemd[1]: Started Watch for WireGuard controller info from data-mesher. peer1 # [297745.549980] peer1 systemd[1]: Started Periodic heartbeat re-publish for dm-wireguard-star peer. peer1 # [297745.550003] peer1 systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container peer1 # [297745.550021] peer1 systemd[1]: Started Daily Cleanup of Temporary Directories. peer1 # [297745.550041] peer1 systemd[1]: Reached target Path Units. peer1 # [297745.550079] peer1 systemd[1]: Reached target Timer Units. peer1 # [297745.550212] peer1 systemd[1]: Listening on D-Bus System Message Bus Socket. peer1 # [297745.550337] peer1 systemd[1]: Listening on Nix Daemon Socket. peer1 # [297745.550466] peer1 systemd[1]: Listening on Virtual Machine and Container Registration Service Socket. peer1 # [297745.550490] peer1 systemd[1]: Reached target Socket Units. peer1 # [297745.550540] peer1 systemd[1]: Reached target Basic System. peer1 # [297745.551897] peer1 systemd[1]: Starting data mesher daemon... peer1 # [297745.552880] peer1 systemd[1]: Starting Import lastlog data into lastlog2 database... peer1 # [297745.553791] peer1 systemd[1]: Starting Name Service Cache Daemon (nsncd)... peer1 # [297745.555134] peer1 systemd[1]: Starting D-Bus System Message Bus... controller # [297745.555883] controller systemd-resolved[140]: Positive Trust Anchors: controller # [297745.555895] controller systemd-resolved[140]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d controller # [297745.555899] controller systemd-resolved[140]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16 controller # [297745.555934] controller systemd-resolved[140]: 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 # [297745.575971] controller systemd-resolved[140]: Using system hostname 'controller'. controller # [297745.577962] controller systemd[1]: Started Network Name Resolution. controller # [297745.578085] controller systemd[1]: Reached target Network. controller # [297745.578211] controller systemd[1]: Reached target System Initialization. controller # [297745.578364] controller systemd[1]: Started Watch for WireGuard peer changes from data-mesher. controller # [297745.578409] controller systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container controller # [297745.578457] controller systemd[1]: Started Daily Cleanup of Temporary Directories. controller # [297745.578494] controller systemd[1]: Reached target Path Units. controller # [297745.578573] controller systemd[1]: Reached target Timer Units. controller # [297745.578786] controller systemd[1]: Listening on D-Bus System Message Bus Socket. controller # [297745.578982] controller systemd[1]: Listening on Nix Daemon Socket. controller # [297745.579197] controller systemd[1]: Listening on Virtual Machine and Container Registration Service Socket. controller # [297745.579236] controller systemd[1]: Reached target Socket Units. controller # [297745.579324] controller systemd[1]: Reached target Basic System. controller # [297745.596581] controller systemd[1]: Starting data mesher daemon... controller # [297745.597995] controller systemd[1]: Starting Import lastlog data into lastlog2 database... controller # [297745.599358] controller systemd[1]: Starting Name Service Cache Daemon (nsncd)... controller # [297745.601465] controller systemd[1]: Starting D-Bus System Message Bus... controller # [297745.619511] controller systemd[1]: Finished Import lastlog data into lastlog2 database. controller # [297745.771753] controller systemd[1]: Started Name Service Cache Daemon (nsncd). controller # [297745.771920] controller nsncd[234]: Oct 19 20:05:50.743 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket" controller # [297745.771819] controller systemd[1]: Reached target Host and Network Name Lookups. controller # [297745.771901] controller systemd[1]: Reached target User and Group Name Lookups. controller # [297745.773477] controller systemd[1]: Starting User Login Management... controller # [297745.774419] controller systemd[1]: Starting Permit User Sessions... peer1 # [297745.613951] peer1 systemd[1]: Finished Import lastlog data into lastlog2 database. peer1 # [297745.800099] peer1 systemd[1]: Started Name Service Cache Daemon (nsncd). peer1 # [297745.800170] peer1 systemd[1]: Reached target Host and Network Name Lookups. peer1 # [297745.800243] peer1 systemd[1]: Reached target User and Group Name Lookups. peer1 # [297745.800550] peer1 nsncd[224]: Oct 19 20:05:50.772 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket" peer1 # [297745.816486] peer1 systemd[1]: Starting User Login Management... peer1 # [297745.817723] peer1 systemd[1]: Starting Permit User Sessions... peer1 # [297745.826733] peer1 systemd[1]: Finished Permit User Sessions. peer1 # [297745.828423] peer1 systemd[1]: Started Console Getty. peer1 # [297745.828499] peer1 systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0 peer1 # [297745.828546] peer1 systemd[1]: Reached target Login Prompts. peer1 # [297745.946531] peer1 dbus-broker-launch[225]: Looking up NSS user entry for 'systemd-timesync'... peer1 # [297745.947800] peer1 dbus-broker-launch[225]: NSS returned no entry for 'systemd-timesync' peer1 # [297745.947800] peer1 dbus-broker-launch[225]: Invalid user-name in /nix/store/76yli3maa0gv1y0wj791a7gjllzh7262-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync" peer1 # [297745.948422] peer1 systemd[1]: Started D-Bus System Message Bus. peer1 # [297745.956484] peer1 dbus-broker-launch[225]: Ready controller # [297745.823920] controller systemd[1]: Finished Permit User Sessions. controller # [297745.825670] controller systemd[1]: Started Console Getty. controller # [297745.825746] controller systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0 controller # [297745.825792] controller systemd[1]: Reached target Login Prompts. controller # [297745.923737] controller dbus-broker-launch[235]: Looking up NSS user entry for 'systemd-timesync'... controller # [297745.925401] controller dbus-broker-launch[235]: NSS returned no entry for 'systemd-timesync' controller # [297745.925401] controller dbus-broker-launch[235]: Invalid user-name in /nix/store/76yli3maa0gv1y0wj791a7gjllzh7262-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync" controller # [297745.925857] controller systemd[1]: Started D-Bus System Message Bus. controller # [297745.932930] controller dbus-broker-launch[235]: Ready controller # [297746.320678] controller data-mesher[232]: time=2026-10-19T20:05:51.292Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo] controller # [297746.321946] controller data-mesher[232]: time=2026-10-19T20:05:51.293Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm: [/dns/controller.clan/tcp/7946]} {12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp: [/dns/peer1.clan/tcp/7946]} {12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2: [/dns/peer2.clan/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm controller # [297746.321946] controller data-mesher[232]: time=2026-10-19T20:05:51.293Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml controller # [297746.325851] controller data-mesher[232]: time=2026-10-19T20:05:51.297Z level=INFO msg="checking file integrity" controller # [297746.325969] controller data-mesher[232]: time=2026-10-19T20:05:51.297Z level=INFO msg="file integrity check complete" controller # [297746.329905] controller data-mesher[232]: time=2026-10-19T20:05:51.301Z level=INFO msg="libp2p host created" peer_id=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm 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::3d42:cd20:395d:7e2d/tcp/7946]" controller # [297746.329956] controller data-mesher[232]: time=2026-10-19T20:05:51.301Z level=INFO msg="registered HTTP route" method=GET path=/files controller # [297746.329956] controller data-mesher[232]: time=2026-10-19T20:05:51.301Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name controller # [297746.329956] controller data-mesher[232]: time=2026-10-19T20:05:51.301Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name controller # [297746.329956] controller data-mesher[232]: time=2026-10-19T20:05:51.301Z level=INFO msg="starting server" controller # [297746.330058] controller data-mesher[232]: time=2026-10-19T20:05:51.301Z level=INFO msg="waiting for DHT to populate" delay=10s controller # [297746.330169] controller data-mesher[232]: time=2026-10-19T20:05:51.302Z level=INFO msg="HTTP server listening" address=[::1]:7331 controller # [297746.330201] controller data-mesher[232]: time=2026-10-19T20:05:51.302Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331 controller # [297746.344573] controller data-mesher[232]: time=2026-10-19T20:05:51.316Z level=INFO msg="peer connected" peer_id=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp remote_addr=/ip4/192.168.1.2/tcp/7946 controller # [297746.532940] controller systemd-logind[252]: New seat seat0. controller # [297746.533143] controller systemd[1]: Started User Login Management. controller # [297746.576618] controller systemd[1]: Starting linger-users.service... peer1 # [297746.329736] peer1 data-mesher[222]: time=2026-10-19T20:05:51.301Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo] peer1 # [297746.330838] peer1 data-mesher[222]: time=2026-10-19T20:05:51.302Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm: [/dns/controller.clan/tcp/7946]} {12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp: [/dns/peer1.clan/tcp/7946]} {12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2: [/dns/peer2.clan/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp peer1 # [297746.330838] peer1 data-mesher[222]: time=2026-10-19T20:05:51.302Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml peer1 # [297746.334012] peer1 data-mesher[222]: time=2026-10-19T20:05:51.305Z level=INFO msg="checking file integrity" peer1 # [297746.334176] peer1 data-mesher[222]: time=2026-10-19T20:05:51.306Z level=INFO msg="file integrity check complete" peer1 # [297746.339414] peer1 data-mesher[222]: time=2026-10-19T20:05:51.311Z level=INFO msg="libp2p host created" peer_id=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp 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::c4b8:fefe:601a:137d/tcp/7946]" peer1 # [297746.339497] peer1 data-mesher[222]: time=2026-10-19T20:05:51.311Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name peer1 # [297746.339497] peer1 data-mesher[222]: time=2026-10-19T20:05:51.311Z level=INFO msg="registered HTTP route" method=GET path=/files peer1 # [297746.339497] peer1 data-mesher[222]: time=2026-10-19T20:05:51.311Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name peer1 # [297746.339497] peer1 data-mesher[222]: time=2026-10-19T20:05:51.311Z level=INFO msg="starting server" peer1 # [297746.339678] peer1 data-mesher[222]: time=2026-10-19T20:05:51.311Z level=INFO msg="waiting for DHT to populate" delay=10s peer1 # [297746.339678] peer1 data-mesher[222]: time=2026-10-19T20:05:51.311Z level=INFO msg="HTTP server listening" address=[::1]:7331 peer1 # [297746.339771] peer1 data-mesher[222]: time=2026-10-19T20:05:51.311Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331 peer1 # [297746.343886] peer1 data-mesher[222]: time=2026-10-19T20:05:51.315Z level=INFO msg="peer connected" peer_id=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm remote_addr=/ip4/192.168.1.1/tcp/7946 peer1 # [297746.464170] peer1 systemd-networkd[216]: eth1: Gained IPv6LL peer1 # [297746.525987] peer1 systemd-logind[242]: New seat seat0. peer1 # [297746.526193] peer1 systemd[1]: Started User Login Management. peer1 # [297746.528208] peer1 systemd[1]: Starting linger-users.service... peer1 # [297746.586978] peer1 systemd[1]: linger-users.service: Deactivated successfully. peer1 # [297746.587274] peer1 systemd[1]: Finished linger-users.service. controller # [297746.591735] controller systemd[1]: linger-users.service: Deactivated successfully. controller # [297746.591874] controller systemd[1]: Finished linger-users.service. controller # [297747.196274] controller systemd-networkd[226]: eth1: Gained IPv6LL controller: still waiting for container 'controller' to reach ready state... controller: (finished: waiting for unit data-mesher.service, in 13.17 seconds) peer1: waiting for unit data-mesher.service peer1 # [297756.331224] peer1 data-mesher[222]: time=2026-10-19T20:06:01.302Z level=INFO msg="received state sync from peer" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297756.331224] peer1 data-mesher[222]: time=2026-10-19T20:06:01.303Z level=INFO msg="merging remote state" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297756.340311] peer1 data-mesher[222]: time=2026-10-19T20:06:01.312Z level=INFO msg="performing state exchange with peers on join" count=1 peer1 # [297756.340400] peer1 data-mesher[222]: time=2026-10-19T20:06:01.312Z level=DEBUG msg="initiating state exchange" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm timeout=5s peer1 # [297756.341128] peer1 data-mesher[222]: time=2026-10-19T20:06:01.312Z level=INFO msg="merging remote state" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297756.341128] peer1 data-mesher[222]: time=2026-10-19T20:06:01.312Z level=INFO msg="state exchange complete" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm timeout=5s peer1 # [297756.341241] peer1 data-mesher[222]: time=2026-10-19T20:06:01.313Z level=INFO msg="server started" peer1 # [297756.341420] peer1 data-mesher[222]: time=2026-10-19T20:06:01.313Z level=INFO msg="starting expired-file sweeper" interval=1m0s peer1 # [297756.341758] peer1 systemd[1]: Started data mesher daemon. peer1 # [297756.368823] peer1 systemd[1]: Starting Publish WireGuard peer info to data-mesher... peer1 # [297756.489731] peer1 data-mesher[222]: time=2026-10-19T20:06:01.461Z level=INFO msg=http_request uri=/files/dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 status=204 peer1 # [297756.490076] peer1 dm-wg-star-publish[288]: Status: 204 No Content peer1 # [297756.492431] peer1 systemd[1]: Starting Reconfigure WireGuard with controller from data-mesher... peer1 # [297756.493115] peer1 systemd[1]: dm-wg-star-wg-star-publish.service: Deactivated successfully. peer1 # [297756.493405] peer1 systemd[1]: Finished Publish WireGuard peer info to data-mesher. peer1 # [297756.495014] peer1 systemd[1]: Reached target Multi-User System. peer1 # [297756.616662] peer1 dm-wg-star-reconfig[316]: No controller data available yet, skipping peer1: (finished: waiting for unit data-mesher.service, in 0.05 seconds) ??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead. File "/nix/store/95nipdc5w3jx72qjsm3qrdj7c0kz7xl1-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/95nipdc5w3jx72qjsm3qrdj7c0kz7xl1-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 # [297756.330556] controller data-mesher[232]: time=2026-10-19T20:06:01.302Z level=INFO msg="performing state exchange with peers on join" count=1 controller # [297756.330556] controller data-mesher[232]: time=2026-10-19T20:06:01.302Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp timeout=5s controller # [297756.331398] controller data-mesher[232]: time=2026-10-19T20:06:01.303Z level=INFO msg="merging remote state" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp controller # [297756.331398] controller data-mesher[232]: time=2026-10-19T20:06:01.303Z level=INFO msg="state exchange complete" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp timeout=5s controller # [297756.331520] controller data-mesher[232]: time=2026-10-19T20:06:01.303Z level=INFO msg="server started" controller # [297756.331689] controller data-mesher[232]: time=2026-10-19T20:06:01.303Z level=INFO msg="starting expired-file sweeper" interval=1m0s controller # [297756.332069] controller systemd[1]: Started data mesher daemon. controller # [297756.334207] controller systemd[1]: Starting Publish WireGuard controller info to data-mesher... controller # [297756.340843] controller data-mesher[232]: time=2026-10-19T20:06:01.312Z level=INFO msg="received state sync from peer" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp controller # [297756.340843] controller data-mesher[232]: time=2026-10-19T20:06:01.312Z level=INFO msg="merging remote state" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp controller # [297756.406476] controller data-mesher[232]: time=2026-10-19T20:06:01.378Z level=INFO msg=http_request uri=/files/dm_wg_star_wg_star/controller status=204 controller # [297756.406827] controller dm-wg-star-publish[297]: Status: 204 No Content controller # [297756.408712] controller systemd[1]: Starting Reconfigure WireGuard peers from data-mesher... controller # [297756.410727] controller systemd[1]: Finished Publish WireGuard controller info to data-mesher. controller # [297756.411521] controller systemd[1]: Reached target Multi-User System. controller # [297756.506000] controller dm-wg-star-reconfig[323]: No peer data available yet, skipping controller # [297756.507383] controller systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully. controller # [297756.528264] controller systemd[1]: Finished Reconfigure WireGuard peers from data-mesher. controller # [297756.528863] controller systemd[1]: Startup finished in 12.496s. peer1 # [297756.617934] peer1 systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully. peer1 # [297756.618089] peer1 systemd[1]: Finished Reconfigure WireGuard with controller from data-mesher. peer1 # [297756.618761] peer1 systemd[1]: Startup finished in 12.632s. 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 . peer1 # [297761.333534] peer1 data-mesher[222]: time=2026-10-19T20:06:06.305Z level=INFO msg="received state sync from peer" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297761.333534] peer1 data-mesher[222]: time=2026-10-19T20:06:06.305Z level=INFO msg="merging remote state" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297761.334272] peer1 data-mesher[222]: time=2026-10-19T20:06:06.305Z level=DEBUG msg="new file detected" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm name=dm_wg_star_wg_star/controller name=dm_wg_star_wg_star/controller peer1 # [297761.334272] peer1 data-mesher[222]: time=2026-10-19T20:06:06.305Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/controller peer1 # [297761.334272] peer1 data-mesher[222]: time=2026-10-19T20:06:06.305Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/controller signed_at="2026-10-19 20:06:01.374 +0000 UTC" signed_by="D4f9zS9/RK5wsBX37rCWkd7yezhj4CuChBZ/HEC3LhA=" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297761.336943] peer1 data-mesher[222]: time=2026-10-19T20:06:06.308Z level=INFO msg="received file request" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 peer1 # [297761.339393] peer1 data-mesher[222]: time=2026-10-19T20:06:06.311Z level=INFO msg="file transfer complete" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 peer1 # [297761.341771] peer1 data-mesher[222]: time=2026-10-19T20:06:06.313Z level=DEBUG msg="attempting push/pull" peer_count=1 peer1 # [297761.341852] peer1 data-mesher[222]: time=2026-10-19T20:06:06.313Z level=DEBUG msg="initiating state exchange" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm timeout=5s peer1 # [297761.342555] peer1 data-mesher[222]: time=2026-10-19T20:06:06.314Z level=INFO msg="download complete" name=dm_wg_star_wg_star/controller signed_at="2026-10-19 20:06:01.374 +0000 UTC" signed_by="D4f9zS9/RK5wsBX37rCWkd7yezhj4CuChBZ/HEC3LhA=" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm written=true elapsed=8.79924ms peer1 # [297761.342767] peer1 systemd[1]: Starting Reconfigure WireGuard with controller from data-mesher... peer1 # [297761.343553] peer1 data-mesher[222]: time=2026-10-19T20:06:06.315Z level=INFO msg="merging remote state" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297761.344221] peer1 data-mesher[222]: time=2026-10-19T20:06:06.316Z level=INFO msg="state exchange complete" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm timeout=5s peer1 # [297761.344285] peer1 data-mesher[222]: time=2026-10-19T20:06:06.316Z level=DEBUG msg="push/pull successful" interval=5s peer1 # [297761.498890] peer1 systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully. peer1 # [297761.499187] peer1 systemd[1]: Finished Reconfigure WireGuard with controller from data-mesher. 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.01 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::3d42:cd20:395d:7e2d controller # [297761.332223] controller data-mesher[232]: time=2026-10-19T20:06:06.304Z level=DEBUG msg="attempting push/pull" peer_count=1 controller # [297761.332941] controller data-mesher[232]: time=2026-10-19T20:06:06.304Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp timeout=5s controller # [297761.334259] controller data-mesher[232]: time=2026-10-19T20:06:06.306Z level=INFO msg="merging remote state" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp controller # [297761.334338] controller data-mesher[232]: time=2026-10-19T20:06:06.306Z level=INFO msg="received file request" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/controller controller # [297761.335407] controller data-mesher[232]: time=2026-10-19T20:06:06.307Z level=DEBUG msg="new file detected" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 controller # [297761.335407] controller data-mesher[232]: time=2026-10-19T20:06:06.307Z level=INFO msg="state exchange complete" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp timeout=5s controller # [297761.335667] controller data-mesher[232]: time=2026-10-19T20:06:06.307Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 controller # [297761.336225] controller data-mesher[232]: time=2026-10-19T20:06:06.308Z level=DEBUG msg="push/pull successful" interval=5s controller # [297761.336225] controller data-mesher[232]: time=2026-10-19T20:06:06.308Z level=INFO msg="file transfer complete" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/controller controller # [297761.336469] controller data-mesher[232]: time=2026-10-19T20:06:06.308Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 signed_at="2026-10-19 20:06:01.457 +0000 UTC" signed_by="UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T/hHkee8=" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp controller # [297761.342459] controller data-mesher[232]: time=2026-10-19T20:06:06.314Z level=INFO msg="received state sync from peer" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp controller # [297761.342518] controller data-mesher[232]: time=2026-10-19T20:06:06.314Z level=INFO msg="merging remote state" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp controller # [297761.343127] controller data-mesher[232]: time=2026-10-19T20:06:06.314Z level=DEBUG msg="new file detected" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 controller # [297761.343224] controller data-mesher[232]: time=2026-10-19T20:06:06.315Z level=INFO msg="download complete" name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 signed_at="2026-10-19 20:06:01.457 +0000 UTC" signed_by="UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T/hHkee8=" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp written=true elapsed=7.422021ms controller # [297761.345812] controller systemd[1]: Starting Reconfigure WireGuard peers from data-mesher... controller # [297761.503812] controller systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully. controller # [297761.503919] controller systemd[1]: Finished Reconfigure WireGuard peers from data-mesher. peer1 # [297766.338006] peer1 data-mesher[222]: time=2026-10-19T20:06:11.309Z level=INFO msg="received state sync from peer" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297766.338006] peer1 data-mesher[222]: time=2026-10-19T20:06:11.309Z level=INFO msg="merging remote state" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297766.344987] peer1 data-mesher[222]: time=2026-10-19T20:06:11.316Z level=DEBUG msg="attempting push/pull" peer_count=1 peer1 # [297766.345084] peer1 data-mesher[222]: time=2026-10-19T20:06:11.316Z level=DEBUG msg="initiating state exchange" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm timeout=5s peer1 # [297766.346559] peer1 data-mesher[222]: time=2026-10-19T20:06:11.318Z level=INFO msg="merging remote state" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297766.347136] peer1 data-mesher[222]: time=2026-10-19T20:06:11.318Z level=INFO msg="state exchange complete" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm timeout=5s peer1 # [297766.347200] peer1 data-mesher[222]: time=2026-10-19T20:06:11.319Z level=DEBUG msg="push/pull successful" interval=5s controller # [297766.337295] controller data-mesher[232]: time=2026-10-19T20:06:11.308Z level=DEBUG msg="attempting push/pull" peer_count=1 controller # [297766.337295] controller data-mesher[232]: time=2026-10-19T20:06:11.309Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp timeout=5s controller # [297766.339018] controller data-mesher[232]: time=2026-10-19T20:06:11.310Z level=INFO msg="merging remote state" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp controller # [297766.339608] controller data-mesher[232]: time=2026-10-19T20:06:11.311Z level=INFO msg="state exchange complete" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp timeout=5s controller # [297766.339674] controller data-mesher[232]: time=2026-10-19T20:06:11.311Z level=DEBUG msg="push/pull successful" interval=5s controller # [297766.345577] controller data-mesher[232]: time=2026-10-19T20:06:11.317Z level=INFO msg="received state sync from peer" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp controller # [297766.345656] controller data-mesher[232]: time=2026-10-19T20:06:11.317Z level=INFO msg="merging remote state" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp peer1: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::3d42:cd20:395d:7e2d, in 6.02 seconds) controller: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::c4b8:fefe:601a:137d controller: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::c4b8:fefe:601a:137d, 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 785) 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 # [297768.864744] peer2 systemd-journald[98]: Journal started peer2 # [297768.864804] peer2 systemd-journald[98]: Runtime Journal (/run/log/journal/5877e8752a084813b16055ac47e0838b) is 8M, max 2.5G, 2.4G free. peer2 # [297768.868991] peer2 systemd[1]: Finished Apply Kernel Variables. peer2 # [297768.880193] peer2 systemd[1]: Finished Create Static Device Nodes in /dev gracefully. peer2 # [297768.892831] peer2 systemd[1]: Starting Flush Journal to Persistent Storage... peer2 # [297768.893595] peer2 systemd[1]: Starting Network Name Resolution... peer2 # [297768.894240] peer2 systemd[1]: Starting Create Static Device Nodes in /dev... peer2 # [297768.903297] peer2 systemd-journald[98]: Time spent on flushing to /var/log/journal/5877e8752a084813b16055ac47e0838b is 1.370ms for 7 entries. peer2 # [297768.903297] peer2 systemd-journald[98]: System Journal (/var/log/journal/5877e8752a084813b16055ac47e0838b) is 8M, max 4G, 3.9G free. peer2 # [297768.917598] peer2 systemd[1]: Finished Flush Journal to Persistent Storage. peer2 # [297768.917990] peer2 systemd[1]: Finished Create Static Device Nodes in /dev. peer2 # [297768.918854] peer2 systemd[1]: Reached target Preparation for Local File Systems. peer2 # [297768.918966] peer2 systemd[1]: Reached target Local File Systems. peer2 # [297768.919825] peer2 systemd[1]: Listening on Boot Loader Control Service Socket. peer2 # [297768.919873] peer2 systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container peer2 # [297768.920728] peer2 systemd[1]: Starting Save Transient machine-id to Disk... peer2 # [297768.921369] peer2 systemd[1]: Starting Create System Files and Directories... peer2 # [297768.921400] peer2 systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys peer2 # [297768.937139] peer2 systemd-tmpfiles[152]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted peer2 # [297768.937325] peer2 systemd-tmpfiles[152]: fchmod() of /var/log/journal failed: Operation not permitted peer2 # [297768.937455] peer2 systemd-tmpfiles[152]: fchmod() of /var/log/journal/5877e8752a084813b16055ac47e0838b failed: Operation not permitted peer2 # [297768.937646] peer2 systemd-tmpfiles[152]: fchmod() of /run/log/journal failed: Operation not permitted peer2 # [297768.938993] peer2 systemd[1]: Finished Create System Files and Directories. peer2 # [297768.940039] peer2 systemd[1]: Starting Rebuild Journal Catalog... peer2 # [297768.940738] peer2 systemd[1]: Starting Record System Boot/Shutdown in UTMP... peer2 # [297768.953399] peer2 systemd[1]: Finished Record System Boot/Shutdown in UTMP. peer2 # [297768.958843] peer2 systemd[1]: Finished Rebuild Journal Catalog. peer2 # [297768.960146] peer2 systemd[1]: Starting Update is Completed... peer2 # [297768.972143] peer2 systemd[1]: Finished Update is Completed. peer2 # [297769.032531] peer2 systemd[1]: Finished Firewall. peer2 # [297769.032677] peer2 systemd[1]: Reached target Preparation for Network. peer2 # [297769.032888] peer2 systemd[1]: Listening on Network Management Resolve Hook Socket. peer2 # [297769.034038] peer2 systemd[1]: Starting Network Management... peer2 # [297769.057929] peer2 systemd[1]: Finished Save Transient machine-id to Disk. peer2 # [297769.639485] peer2 systemd-networkd[215]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted peer2 # [297769.639573] peer2 systemd-networkd[215]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted peer2 # [297769.649026] peer2 systemd-networkd[215]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section. peer2 # [297769.649194] peer2 systemd-networkd[215]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section. peer2 # [297769.649332] peer2 systemd-networkd[215]: lo: Link UP peer2 # [297769.649337] peer2 systemd-networkd[215]: lo: Gained carrier peer2 # [297769.649507] peer2 systemd-networkd[215]: eth1: Configuring with /etc/systemd/network/40-eth1.network. peer2 # [297769.649924] peer2 systemd[1]: Started Network Management. peer2 # [297769.650422] peer2 systemd-networkd[215]: wg-star: Configuring with /etc/systemd/network/40-wg-star.network. peer2 # [297769.650712] peer2 systemd-networkd[215]: wg-star: netdev ready peer2 # [297769.651113] peer2 systemd-networkd[215]: eth1: Link UP peer2 # [297769.651730] peer2 systemd-networkd[215]: eth1: Gained carrier peer2 # [297769.651757] peer2 systemd[1]: Starting Enable Persistent Storage in systemd-networkd... peer2 # [297769.700379] peer2 systemd-networkd[215]: wg-star: Link UP peer2 # [297769.700384] peer2 systemd-networkd[215]: wg-star: Gained carrier peer2 # [297769.709938] peer2 systemd[1]: Finished Enable Persistent Storage in systemd-networkd. peer2 # [297769.860374] peer2 systemd[1]: etc-machine\x2did.mount: Deactivated successfully. peer2 # [297769.911841] peer2 systemd-resolved[131]: Positive Trust Anchors: peer2 # [297769.911855] peer2 systemd-resolved[131]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d peer2 # [297769.911858] peer2 systemd-resolved[131]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16 peer2 # [297769.911892] peer2 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 peer2 # [297769.931915] peer2 systemd-resolved[131]: Using system hostname 'peer2'. peer2 # [297769.933508] peer2 systemd[1]: Started Network Name Resolution. peer2 # [297769.933637] peer2 systemd[1]: Reached target Network. peer2 # [297769.933756] peer2 systemd[1]: Reached target System Initialization. peer2 # [297769.933922] peer2 systemd[1]: Started Watch for WireGuard controller info from data-mesher. peer2 # [297769.933973] peer2 systemd[1]: Started Periodic heartbeat re-publish for dm-wireguard-star peer. peer2 # [297769.934011] peer2 systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container peer2 # [297769.934046] peer2 systemd[1]: Started Daily Cleanup of Temporary Directories. peer2 # [297769.934086] peer2 systemd[1]: Reached target Path Units. peer2 # [297769.934151] peer2 systemd[1]: Reached target Timer Units. peer2 # [297769.934366] peer2 systemd[1]: Listening on D-Bus System Message Bus Socket. peer2 # [297769.934580] peer2 systemd[1]: Listening on Nix Daemon Socket. peer2 # [297769.934802] peer2 systemd[1]: Listening on Virtual Machine and Container Registration Service Socket. peer2 # [297769.934848] peer2 systemd[1]: Reached target Socket Units. peer2 # [297769.934920] peer2 systemd[1]: Reached target Basic System. peer2 # [297769.937091] peer2 systemd[1]: Starting data mesher daemon... peer2 # [297769.938423] peer2 systemd[1]: Starting Import lastlog data into lastlog2 database... peer2 # [297769.939831] peer2 systemd[1]: Starting Name Service Cache Daemon (nsncd)... peer2 # [297769.941945] peer2 systemd[1]: Starting D-Bus System Message Bus... peer2 # [297770.010384] peer2 systemd[1]: Finished Import lastlog data into lastlog2 database. peer2 # [297770.163689] peer2 systemd[1]: Started Name Service Cache Daemon (nsncd). peer2 # [297770.163792] peer2 systemd[1]: Reached target Host and Network Name Lookups. peer2 # [297770.163892] peer2 systemd[1]: Reached target User and Group Name Lookups. peer2 # [297770.164171] peer2 nsncd[223]: Oct 19 20:06:15.135 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket" peer2 # [297770.166006] peer2 systemd[1]: Starting User Login Management... peer2 # [297770.167540] peer2 systemd[1]: Starting Permit User Sessions... peer2 # [297770.216547] peer2 systemd[1]: Finished Permit User Sessions. peer2 # [297770.218571] peer2 systemd[1]: Started Console Getty. peer2 # [297770.218654] peer2 systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0 peer2 # [297770.218697] peer2 systemd[1]: Reached target Login Prompts. peer2 # [297770.298691] peer2 dbus-broker-launch[224]: Looking up NSS user entry for 'systemd-timesync'... peer2 # [297770.300333] peer2 dbus-broker-launch[224]: NSS returned no entry for 'systemd-timesync' peer2 # [297770.300421] peer2 dbus-broker-launch[224]: Invalid user-name in /nix/store/76yli3maa0gv1y0wj791a7gjllzh7262-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync" peer2 # [297770.300820] peer2 systemd[1]: Started D-Bus System Message Bus. peer2 # [297770.309843] peer2 dbus-broker-launch[224]: Ready peer2 # [297770.676347] peer2 data-mesher[221]: time=2026-10-19T20:06:15.648Z level=DEBUG msg="http config" listen_addresses="[[::1]:7331 127.0.0.1:7331]" port=7331 interfaces=[lo] peer2 # [297770.677433] peer2 data-mesher[221]: time=2026-10-19T20:06:15.649Z level=DEBUG msg="cluster config" port=7946 interfaces=[] bootstrap_peers="[{12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm: [/dns/controller.clan/tcp/7946]} {12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp: [/dns/peer1.clan/tcp/7946]} {12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2: [/dns/peer2.clan/tcp/7946]}]" push_pull_interval=5s peer_id=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 peer2 # [297770.677433] peer2 data-mesher[221]: time=2026-10-19T20:06:15.649Z level=INFO msg="config loaded" config_file=/etc/data-mesher/dm.toml peer2 # [297770.684579] peer2 data-mesher[221]: time=2026-10-19T20:06:15.656Z level=INFO msg="checking file integrity" peer2 # [297770.684737] peer2 data-mesher[221]: time=2026-10-19T20:06:15.656Z level=INFO msg="file integrity check complete" peer2 # [297770.690329] peer2 data-mesher[221]: time=2026-10-19T20:06:15.662Z level=INFO msg="libp2p host created" peer_id=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 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::6bbf:f84:ba97:d885/tcp/7946]" peer2 # [297770.690403] peer2 data-mesher[221]: time=2026-10-19T20:06:15.662Z level=INFO msg="registered HTTP route" method=PUT path=/files/:name peer2 # [297770.690403] peer2 data-mesher[221]: time=2026-10-19T20:06:15.662Z level=INFO msg="registered HTTP route" method=DELETE path=/files/:name peer2 # [297770.690403] peer2 data-mesher[221]: time=2026-10-19T20:06:15.662Z level=INFO msg="registered HTTP route" method=GET path=/files peer2 # [297770.690403] peer2 data-mesher[221]: time=2026-10-19T20:06:15.662Z level=INFO msg="starting server" peer2 # [297770.690523] peer2 data-mesher[221]: time=2026-10-19T20:06:15.662Z level=INFO msg="waiting for DHT to populate" delay=10s peer2 # [297770.690658] peer2 data-mesher[221]: time=2026-10-19T20:06:15.662Z level=INFO msg="HTTP server listening" address=[::1]:7331 peer2 # [297770.690702] peer2 data-mesher[221]: time=2026-10-19T20:06:15.662Z level=INFO msg="HTTP server listening" address=127.0.0.1:7331 peer2 # [297770.696242] peer2 data-mesher[221]: time=2026-10-19T20:06:15.668Z level=INFO msg="peer connected" peer_id=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp remote_addr=/ip4/192.168.1.2/tcp/7946 peer2 # [297770.705646] peer2 data-mesher[221]: time=2026-10-19T20:06:15.677Z level=INFO msg="peer connected" peer_id=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm remote_addr=/ip4/192.168.1.1/tcp/7946 peer2 # [297770.914760] peer2 systemd-logind[241]: New seat seat0. peer2 # [297770.915020] peer2 systemd[1]: Started User Login Management. peer2 # [297770.917563] peer2 systemd[1]: Starting linger-users.service... peer1 # [297770.697960] peer1 data-mesher[222]: time=2026-10-19T20:06:15.669Z level=INFO msg="peer connected" peer_id=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 remote_addr=/ip4/192.168.1.3/tcp/7946 controller # [297770.707441] controller data-mesher[232]: time=2026-10-19T20:06:15.679Z level=INFO msg="peer connected" peer_id=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 remote_addr=/ip4/192.168.1.3/tcp/7946 peer2 # [297770.966933] peer2 systemd[1]: linger-users.service: Deactivated successfully. peer2 # [297770.967270] peer2 systemd[1]: Finished linger-users.service. peer1 # [297771.340940] peer1 data-mesher[222]: time=2026-10-19T20:06:16.312Z level=INFO msg="received state sync from peer" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297771.340940] peer1 data-mesher[222]: time=2026-10-19T20:06:16.312Z level=INFO msg="merging remote state" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297771.348039] peer1 data-mesher[222]: time=2026-10-19T20:06:16.319Z level=DEBUG msg="attempting push/pull" peer_count=1 peer1 # [297771.348039] peer1 data-mesher[222]: time=2026-10-19T20:06:16.319Z level=DEBUG msg="initiating state exchange" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm timeout=5s peer1 # [297771.349657] peer1 data-mesher[222]: time=2026-10-19T20:06:16.321Z level=INFO msg="merging remote state" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer1 # [297771.350232] peer1 data-mesher[222]: time=2026-10-19T20:06:16.322Z level=INFO msg="state exchange complete" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm timeout=5s peer1 # [297771.350313] peer1 data-mesher[222]: time=2026-10-19T20:06:16.322Z level=DEBUG msg="push/pull successful" interval=5s controller # [297771.340131] controller data-mesher[232]: time=2026-10-19T20:06:16.311Z level=DEBUG msg="attempting push/pull" peer_count=1 controller # [297771.340131] controller data-mesher[232]: time=2026-10-19T20:06:16.312Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp timeout=5s controller # [297771.341943] controller data-mesher[232]: time=2026-10-19T20:06:16.313Z level=INFO msg="merging remote state" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp controller # [297771.342529] controller data-mesher[232]: time=2026-10-19T20:06:16.314Z level=INFO msg="state exchange complete" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp timeout=5s controller # [297771.342619] controller data-mesher[232]: time=2026-10-19T20:06:16.314Z level=DEBUG msg="push/pull successful" interval=5s controller # [297771.348603] controller data-mesher[232]: time=2026-10-19T20:06:16.320Z level=INFO msg="received state sync from peer" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp controller # [297771.348603] controller data-mesher[232]: time=2026-10-19T20:06:16.320Z level=INFO msg="merging remote state" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp peer2 # [297771.452154] peer2 systemd-networkd[215]: eth1: Gained IPv6LL peer2 # [297776.344130] peer2 data-mesher[221]: time=2026-10-19T20:06:21.315Z level=INFO msg="received state sync from peer" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer2 # [297776.344130] peer2 data-mesher[221]: time=2026-10-19T20:06:21.315Z level=INFO msg="merging remote state" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer2 # [297776.344864] peer2 data-mesher[221]: time=2026-10-19T20:06:21.316Z level=DEBUG msg="new file detected" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 peer2 # [297776.344864] peer2 data-mesher[221]: time=2026-10-19T20:06:21.316Z level=DEBUG msg="new file detected" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 name=dm_wg_star_wg_star/controller name=dm_wg_star_wg_star/controller peer2 # [297776.344864] peer2 data-mesher[221]: time=2026-10-19T20:06:21.316Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 peer2 # [297776.344864] peer2 data-mesher[221]: time=2026-10-19T20:06:21.316Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/controller peer2 # [297776.344864] peer2 data-mesher[221]: time=2026-10-19T20:06:21.316Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/controller signed_at="2026-10-19 20:06:01.374 +0000 UTC" signed_by="D4f9zS9/RK5wsBX37rCWkd7yezhj4CuChBZ/HEC3LhA=" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer2 # [297776.344864] peer2 data-mesher[221]: time=2026-10-19T20:06:21.316Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 signed_at="2026-10-19 20:06:01.457 +0000 UTC" signed_by="UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T/hHkee8=" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer2 # [297776.351158] peer2 data-mesher[221]: time=2026-10-19T20:06:21.322Z level=INFO msg="received state sync from peer" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp peer2 # [297776.351158] peer2 data-mesher[221]: time=2026-10-19T20:06:21.323Z level=INFO msg="merging remote state" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp peer2 # [297776.351765] peer2 data-mesher[221]: time=2026-10-19T20:06:21.323Z level=DEBUG msg="new file detected" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 peer2 # [297776.351846] peer2 data-mesher[221]: time=2026-10-19T20:06:21.323Z level=DEBUG msg="new file detected" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 name=dm_wg_star_wg_star/controller name=dm_wg_star_wg_star/controller peer2 # [297776.352064] peer2 systemd[1]: Starting Reconfigure WireGuard with controller from data-mesher... peer2 # [297776.354324] peer2 data-mesher[221]: time=2026-10-19T20:06:21.326Z level=INFO msg="download complete" name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 signed_at="2026-10-19 20:06:01.457 +0000 UTC" signed_by="UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T/hHkee8=" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm written=true elapsed=9.590651ms peer2 # [297776.355291] peer2 data-mesher[221]: time=2026-10-19T20:06:21.327Z level=INFO msg="download complete" name=dm_wg_star_wg_star/controller signed_at="2026-10-19 20:06:01.374 +0000 UTC" signed_by="D4f9zS9/RK5wsBX37rCWkd7yezhj4CuChBZ/HEC3LhA=" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm written=true elapsed=10.586104ms peer2 # [297776.491453] peer2 systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully. peer2 # [297776.491808] peer2 systemd[1]: Finished Reconfigure WireGuard with controller from data-mesher. peer1 # [297776.350573] peer1 data-mesher[222]: time=2026-10-19T20:06:21.322Z level=DEBUG msg="attempting push/pull" peer_count=1 peer1 # [297776.350974] peer1 data-mesher[222]: time=2026-10-19T20:06:21.322Z level=DEBUG msg="initiating state exchange" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 timeout=5s peer1 # [297776.352041] peer1 data-mesher[222]: time=2026-10-19T20:06:21.323Z level=INFO msg="merging remote state" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 peer1 # [297776.352041] peer1 data-mesher[222]: time=2026-10-19T20:06:21.323Z level=INFO msg="state exchange complete" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 timeout=5s peer1 # [297776.352220] peer1 data-mesher[222]: time=2026-10-19T20:06:21.323Z level=DEBUG msg="push/pull successful" interval=5s controller # [297776.343377] controller data-mesher[232]: time=2026-10-19T20:06:21.315Z level=DEBUG msg="attempting push/pull" peer_count=1 controller # [297776.343377] controller data-mesher[232]: time=2026-10-19T20:06:21.315Z level=DEBUG msg="initiating state exchange" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 timeout=5s controller # [297776.344852] controller data-mesher[232]: time=2026-10-19T20:06:21.316Z level=INFO msg="merging remote state" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 controller # [297776.344852] controller data-mesher[232]: time=2026-10-19T20:06:21.316Z level=INFO msg="state exchange complete" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 timeout=5s controller # [297776.344852] controller data-mesher[232]: time=2026-10-19T20:06:21.316Z level=DEBUG msg="push/pull successful" interval=5s controller # [297776.345361] controller data-mesher[232]: time=2026-10-19T20:06:21.317Z level=INFO msg="received file request" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 controller # [297776.345528] controller data-mesher[232]: time=2026-10-19T20:06:21.317Z level=INFO msg="received file request" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/controller controller # [297776.345649] controller data-mesher[232]: time=2026-10-19T20:06:21.317Z level=INFO msg="file transfer complete" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/UTMh641oTZxFDjyZhr8kspYV9UI9WOy2un8T_hHkee8 controller # [297776.347936] controller data-mesher[232]: time=2026-10-19T20:06:21.319Z level=INFO msg="file transfer complete" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/controller peer2: still waiting for container 'peer2' to reach ready state... peer1 # [297780.691983] peer1 data-mesher[222]: time=2026-10-19T20:06:25.663Z level=INFO msg="received state sync from peer" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 peer1 # [297780.691983] peer1 data-mesher[222]: time=2026-10-19T20:06:25.663Z level=INFO msg="merging remote state" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 peer2 # [297780.691105] peer2 data-mesher[221]: time=2026-10-19T20:06:25.662Z level=INFO msg="performing state exchange with peers on join" count=1 peer2 # [297780.691105] peer2 data-mesher[221]: time=2026-10-19T20:06:25.662Z level=DEBUG msg="initiating state exchange" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp timeout=5s peer2 # [297780.692888] peer2 data-mesher[221]: time=2026-10-19T20:06:25.664Z level=INFO msg="merging remote state" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp peer2 # [297780.693489] peer2 data-mesher[221]: time=2026-10-19T20:06:25.665Z level=INFO msg="state exchange complete" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp timeout=5s peer2 # [297780.693549] peer2 data-mesher[221]: time=2026-10-19T20:06:25.665Z level=INFO msg="server started" peer2 # [297780.693731] peer2 data-mesher[221]: time=2026-10-19T20:06:25.665Z level=INFO msg="starting expired-file sweeper" interval=1m0s peer2 # [297780.693976] peer2 systemd[1]: Started data mesher daemon. peer2 # [297780.696492] peer2 systemd[1]: Starting Publish WireGuard peer info to data-mesher... peer2 # [297780.866941] peer2 systemd[1]: Starting Reconfigure WireGuard with controller from data-mesher... peer2 # [297780.869010] peer2 data-mesher[221]: time=2026-10-19T20:06:25.840Z level=INFO msg=http_request uri=/files/dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U status=204 peer2 # [297780.869442] peer2 dm-wg-star-publish[297]: Status: 204 No Content peer2 # [297780.872943] peer2 systemd[1]: dm-wg-star-wg-star-publish.service: Deactivated successfully. peer2 # [297780.900270] peer2 systemd[1]: Finished Publish WireGuard peer info to data-mesher. peer2 # [297780.901027] peer2 systemd[1]: Reached target Multi-User System. peer2 # [297781.011552] peer2 systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully. peer2 # [297781.011898] peer2 systemd[1]: Finished Reconfigure WireGuard with controller from data-mesher. peer2 # [297781.012571] peer2 systemd[1]: Startup finished in 12.654s. peer2 # [297781.346762] peer2 data-mesher[221]: time=2026-10-19T20:06:26.318Z level=INFO msg="received state sync from peer" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer2 # [297781.346762] peer2 data-mesher[221]: time=2026-10-19T20:06:26.318Z level=INFO msg="merging remote state" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm peer2: (finished: waiting for unit data-mesher.service, in 13.67 seconds) ??? Warning (UserWarning): wait_until_succeeds(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead. File "/nix/store/95nipdc5w3jx72qjsm3qrdj7c0kz7xl1-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/95nipdc5w3jx72qjsm3qrdj7c0kz7xl1-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39 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 0.01 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 . 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::3d42:cd20:395d:7e2d peer2: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::3d42:cd20:395d:7e2d, in 0.01 seconds) controller: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::6bbf:0f84:ba97:d885 controller: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::6bbf:0f84:ba97:d885, in 0.01 seconds) peer1: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::6bbf:0f84:ba97:d885 peer1: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::6bbf:0f84:ba97:d885, in 0.01 seconds) peer2: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::c4b8:fefe:601a:137d peer2: (finished: waiting for success: ping -6 -c1 -W5 fda1:05c8:00::c4b8:fefe:601a:137d, in 0.01 seconds) (finished: run the VM test script, in 38.13 seconds) test script finished in 38.21s cleanup kill NspawnMachine (pid 50) controller # [297781.345844] controller data-mesher[232]: time=2026-10-19T20:06:26.317Z level=DEBUG msg="attempting push/pull" peer_count=1 controller # [297781.346563] controller data-mesher[232]: time=2026-10-19T20:06:26.317Z level=DEBUG msg="initiating state exchange" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 timeout=5s controller # [297781.348358] controller data-mesher[232]: time=2026-10-19T20:06:26.320Z level=INFO msg="merging remote state" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 controller # [297781.348864] controller data-mesher[232]: time=2026-10-19T20:06:26.320Z level=DEBUG msg="new file detected" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U controller # [297781.349003] controller data-mesher[232]: time=2026-10-19T20:06:26.320Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U controller # [297781.349069] controller data-mesher[232]: time=2026-10-19T20:06:26.320Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U signed_at="2026-10-19 20:06:25.832 +0000 UTC" signed_by="CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf/G7HG7/TqMy+U=" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 controller # [297781.349422] controller data-mesher[232]: time=2026-10-19T20:06:26.321Z level=INFO msg="state exchange complete" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 timeout=5s controller # [297781.349490] controller data-mesher[232]: time=2026-10-19T20:06:26.321Z level=DEBUG msg="push/pull successful" interval=5s controller # [297781.352672] controller data-mesher[232]: time=2026-10-19T20:06:26.324Z level=INFO msg="download complete" name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U signed_at="2026-10-19 20:06:25.832 +0000 UTC" signed_by="CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf/G7HG7/TqMy+U=" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 written=true elapsed=3.626809ms controller # [297781.355346] controller systemd[1]: Starting Reconfigure WireGuard peers from data-mesher... controller # [297781.504991] controller systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully. controller # [297781.505253] controller systemd[1]: Finished Reconfigure WireGuard peers from data-mesher. peer2 # [297781.349506] peer2 data-mesher[221]: time=2026-10-19T20:06:26.321Z level=INFO msg="received file request" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U peer2 # [297781.350385] peer2 data-mesher[221]: time=2026-10-19T20:06:26.322Z level=INFO msg="file transfer complete" peer=12D3KooWCA1dih9tVNzpbtUqtvMr3SXMqNjUZmSGcn2NpxmwwSqm network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U peer2 # [297781.353572] peer2 data-mesher[221]: time=2026-10-19T20:06:26.325Z level=INFO msg="received state sync from peer" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp peer2 # [297781.353644] peer2 data-mesher[221]: time=2026-10-19T20:06:26.325Z level=INFO msg="merging remote state" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp peer2 # [297781.356071] peer2 data-mesher[221]: time=2026-10-19T20:06:26.327Z level=INFO msg="received file request" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U peer2 # [297781.358297] peer2 data-mesher[221]: time=2026-10-19T20:06:26.330Z level=INFO msg="file transfer complete" peer=12D3KooWFHLQyXWyKyDuPm8FFocdAmFyXRMgjbkX9F9fGPqpTbmp network="8kzkQ1KnEO8sIibkmcYrA5Q2afPXKomHPukpjKq+xPw=" name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U peer1 # [297781.352930] peer1 data-mesher[222]: time=2026-10-19T20:06:26.324Z level=DEBUG msg="attempting push/pull" peer_count=1 peer1 # [297781.352930] peer1 data-mesher[222]: time=2026-10-19T20:06:26.324Z level=DEBUG msg="initiating state exchange" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 timeout=5s peer1 # [297781.354705] peer1 data-mesher[222]: time=2026-10-19T20:06:26.326Z level=INFO msg="merging remote state" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 peer1 # [297781.355276] peer1 data-mesher[222]: time=2026-10-19T20:06:26.327Z level=DEBUG msg="new file detected" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U peer1 # [297781.355442] peer1 data-mesher[222]: time=2026-10-19T20:06:26.327Z level=INFO msg="scheduling file download" name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U peer1 # [297781.355530] peer1 data-mesher[222]: time=2026-10-19T20:06:26.327Z level=INFO msg="downloading file" name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U signed_at="2026-10-19 20:06:25.832 +0000 UTC" signed_by="CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf/G7HG7/TqMy+U=" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 peer1 # [297781.355875] peer1 data-mesher[222]: time=2026-10-19T20:06:26.327Z level=INFO msg="state exchange complete" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 timeout=5s peer1 # [297781.355999] peer1 data-mesher[222]: time=2026-10-19T20:06:26.327Z level=DEBUG msg="push/pull successful" interval=5s peer1 # [297781.360345] peer1 data-mesher[222]: time=2026-10-19T20:06:26.332Z level=INFO msg="download complete" name=dm_wg_star_wg_star/CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf_G7HG7_TqMy-U signed_at="2026-10-19 20:06:25.832 +0000 UTC" signed_by="CX5WkYFz0KcEC8K0GKvXxC1G2DSSDf/G7HG7/TqMy+U=" peer=12D3KooWATRa98EEFjJNMieiztMKxc527tx9Fni2Fz5vKw7kiVf2 written=true elapsed=4.861107ms peer1 # [297781.385045] peer1 systemd[1]: Starting Reconfigure WireGuard with controller from data-mesher... peer1 # [297781.507862] peer1 systemd[1]: dm-wg-star-wg-star-reconfig.service: Deactivated successfully. peer1 # [297781.508043] peer1 systemd[1]: Finished Reconfigure WireGuard with controller from data-mesher. kill NspawnMachine (pid 53) Container controller terminated by signal KILL. kill NspawnMachine (pid 785) Container peer1 terminated by signal KILL. Container peer2 terminated by signal KILL. (finished: cleanup, in 0.55 seconds)