Anyone else got BTRFS send failures since 5.7?

DanielBull · October 27, 2022, 4:43pm

I have a pair of LXD servers set up with a number of containers on server A which refresh to server B every night using:
lxc copy --refresh container serverb:container --storage=default --refresh --mode=relay

They have been functioning well for a considerable time (the lxd team has helped in the past with previous problems - thanks!).

In the last few days or so (I’m guessing coinciding with the release of 5.7?) I’ve suddenly started getting what appear to be random send failures, there doesn’t seem to be any pattern to which containers get hit.

Here’s a few from last night…

Error: Error transferring instance data: Failed sending volume gogs/2022-10-27-daily:/: Btrfs send failed: [signal: killed write unix /var/snap/lxd/common/lxd/unix.socket->@: write: broken pipe] (At subvol /var/snap/lxd/common/lxd/storage-pools/srv/containers-snapshots/gogs/2022-10-27-daily
Error: Error transferring instance data: Failed sending volume librenms/2022-10-26-daily:/: Btrfs send failed: [signal: killed write unix /var/snap/lxd/common/lxd/unix.socket->@: write: broken pipe] (At subvol /var/snap/lxd/common/lxd/storage-pools/srv/containers-snapshots/librenms/2022-10-26-daily
Error: Error transferring instance data: Failed sending volume media/2022-10-27-daily:/: Btrfs send failed: [signal: killed write unix /var/snap/lxd/common/lxd/unix.socket->@: write: broken pipe] (At subvol /var/snap/lxd/common/lxd/storage-pools/srv/containers-snapshots/media/2022-10-27-daily
Error: Error transferring instance data: Failed sending volume unifi/2022-10-26-daily:/: Btrfs send failed: [signal: killed write unix /var/snap/lxd/common/lxd/unix.socket->@: write: broken pipe] (At subvol /var/snap/lxd/common/lxd/storage-pools/srv/containers-snapshots/unifi/2022-10-26-daily
Error: Error transferring instance data: Failed sending volume wireguard/2022-10-27-daily:/: Btrfs send failed: [signal: killed write unix /var/snap/lxd/common/lxd/unix.socket->@: write: broken pipe] (At subvol /var/snap/lxd/common/lxd/storage-pools/srv/containers-snapshots/wireguard/2022-10-27-daily

Those were mostly from the snapshots but I’m also getting the errors on the master containers.

Just to check it wasn’t some form of random corruption I removed one of the containers completely from the destination server…
lxc delete serverb:jitsi

Stopped it locally and attempted to copy it across fresh…

lxc stop jitsi
lxc copy jitsi serverb:jitsi --storage=default --mode=relay

It ran for a while then…

Error: Error transferring instance data: Failed sending volume jitsi/2022-09-01-monthly:/: Btrfs send failed: [signal: killed write unix /var/snap/lxd/common/lxd/unix.socket->@: write: broken pipe] (At subvol /var/snap/lxd/common/lxd/storage-pools/srv/containers-snapshots/jitsi/2022-09-01-monthly
)

Fetching the log on all the containers I’ve checked so far has the same errors…

lxc info jitsi --show-log

.
.

Log:

lxc jitsi 20221027163309.418 WARN     conf - ../src/src/lxc/conf.c:lxc_map_ids:3592 - newuidmap binary is missing
lxc jitsi 20221027163309.418 WARN     conf - ../src/src/lxc/conf.c:lxc_map_ids:3598 - newgidmap binary is missing
lxc jitsi 20221027163309.420 WARN     conf - ../src/src/lxc/conf.c:lxc_map_ids:3592 - newuidmap binary is missing
lxc jitsi 20221027163309.420 WARN     conf - ../src/src/lxc/conf.c:lxc_map_ids:3598 - newgidmap binary is missing
lxc jitsi 20221027163309.421 WARN     cgfsng - ../src/src/lxc/cgroups/cgfsng.c:fchowmodat:1611 - No such file or directory - Failed to fchownat(40, memory.o
om.group, 1000000000, 0, AT_EMPTY_PATH | AT_SYMLINK_NOFOLLOW )

Fetching /var/snap/lxd/common/lxd/logs/lxd.log shows lots of instances of the following…

time="2022-10-27T16:05:52+01:00" level=error msg="Failed extracting TCP connection from remote connection" err="Connection is not a net.TCPConn"

and

time="2022-10-27T16:06:26+01:00" level=error msg="Migration failed on source" err="Failed sending volume jitsi/2022-09-01-monthly:/: Btrfs send failed: [sig
nal: killed write unix /var/snap/lxd/common/lxd/unix.socket->@: write: broken pipe] (At subvol /var/snap/lxd/common/lxd/storage-pools/srv/containers-snapsho
ts/jitsi/2022-09-01-monthly\n)" instance=jitsi project="{{map[features.images:true features.networks:true features.profiles:true features.storage.buckets:tr
ue features.storage.volumes:true] Default LXD project} default []}"

Both machines are Ubuntu 20.04.5 LTS running LXD 5.7 on top of BTRFS

Any help would be appreciated…

tomp · October 27, 2022, 9:14pm

What does /var/snap/lxd/common/lxd/logs/lxd.log show on the receiving side?

Also, how far, in terms of latency, are the servers from your client?

DanielBull · October 28, 2022, 7:45am

No recent entries in lxd.log on the receiving side at all. Everything is from a log time ago.

Latency is consistent between 9 and 12ms. Occasional blips as high as 20ms but thats about it. This was tested both before and whilst the lxc copy was running. Zero packet loss.

tomp · October 28, 2022, 8:36am

Please can you run lxc monitor --type=logging --pretty on each LXD server, as you run the relay copy operation and capture the output here. Thanks

DanielBull · October 28, 2022, 11:22am

Thanks for your help Tom, see below…

Server A - the sending server

DEBUG  [2022-10-28T12:06:28+01:00] Event listener server handler started         id=8874d0c5-1723-4e38-980f-9274710f8f7e local=/var/snap/lxd/common/lxd/unix.socket remote=@
DEBUG  [2022-10-28T12:06:40+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0 username=root
DEBUG  [2022-10-28T12:06:40+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/instances/jitsi username=root
DEBUG  [2022-10-28T12:06:40+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/events username=root
DEBUG  [2022-10-28T12:06:40+01:00] Event listener server handler started         id=a4972008-8e31-4e1e-9104-d212d812dc93 local=/var/snap/lxd/common/lxd/unix.socket remote=@
DEBUG  [2022-10-28T12:06:40+01:00] Handling API request                          ip=@ method=POST protocol=unix url=/1.0/instances/jitsi username=root
DEBUG  [2022-10-28T12:06:40+01:00] New operation                                 class=websocket description="Migrating instance" operation=e983a5e6-7901-427a-9ca8-db0800d34479 project=default
INFO   [2022-10-28T12:06:40+01:00] Waiting for migration channel connections on source  instance=jitsi project="{{map[features.images:true features.networks:true features.profiles:true features.storage.buckets:true features.storage.volumes:true] Default LXD project} default []}"
DEBUG  [2022-10-28T12:06:40+01:00] Started operation                             class=websocket description="Migrating instance" operation=e983a5e6-7901-427a-9ca8-db0800d34479 project=default
DEBUG  [2022-10-28T12:06:40+01:00] Connecting to operation                       class=websocket description="Migrating instance" operation=e983a5e6-7901-427a-9ca8-db0800d34479 project=default
DEBUG  [2022-10-28T12:06:40+01:00] Handling API request                          ip=@ method=GET protocol=unix url="/1.0/operations/e983a5e6-7901-427a-9ca8-db0800d34479/websocket?secret=45de9a247e43baea7c21e8b94f96cbe85742a9f5e7faec5534c137828773eb17" username=root
DEBUG  [2022-10-28T12:06:40+01:00] Connected to operation                        class=websocket description="Migrating instance" operation=e983a5e6-7901-427a-9ca8-db0800d34479 project=default
ERROR  [2022-10-28T12:06:40+01:00] Failed extracting TCP connection from remote connection  err="Connection is not a net.TCPConn"
DEBUG  [2022-10-28T12:06:40+01:00] Connecting to operation                       class=websocket description="Migrating instance" operation=e983a5e6-7901-427a-9ca8-db0800d34479 project=default
DEBUG  [2022-10-28T12:06:40+01:00] Handling API request                          ip=@ method=GET protocol=unix url="/1.0/operations/e983a5e6-7901-427a-9ca8-db0800d34479/websocket?secret=b8f8de57ab2507e4787b0cf2c50af6ab828b653066396f27100101ccbd07f0d0" username=root
ERROR  [2022-10-28T12:06:40+01:00] Failed extracting TCP connection from remote connection  err="Connection is not a net.TCPConn"
INFO   [2022-10-28T12:06:40+01:00] Migration channels connected on source        instance=jitsi project="{{map[features.images:true features.networks:true features.profiles:true features.storage.buckets:true features.storage.volumes:true] Default LXD project} default []}"
DEBUG  [2022-10-28T12:06:40+01:00] Connected to operation                        class=websocket description="Migrating instance" operation=e983a5e6-7901-427a-9ca8-db0800d34479 project=default
DEBUG  [2022-10-28T12:06:42+01:00] MigrateInstance started                       args="&{IndexHeaderVersion:1 Name:jitsi Snapshots:[2022-09-01-monthly 2022-10-01-monthly 2022-10-02-weekly 2022-10-09-weekly 2022-10-16-weekly 2022-10-22-daily 2022-10-23-daily 2022-10-23-weekly 2022-10-24-daily 2022-10-25-daily 2022-10-26-daily 2022-10-27-daily 2022-10-28-daily] MigrationType:{FSType:BTRFS Features:[migration_header header_subvolumes header_subvolume_uuids]} TrackProgress:true MultiSync:true FinalSync:false Data:<nil> ContentType: AllowInconsistent:false Refresh:true Info:0xc0003965a0 VolumeOnly:false}" instance=jitsi project=default
DEBUG  [2022-10-28T12:06:42+01:00] Sent migration index header, waiting for response  args="&{IndexHeaderVersion:1 Name:jitsi Snapshots:[2022-09-01-monthly 2022-10-01-monthly 2022-10-02-weekly 2022-10-09-weekly 2022-10-16-weekly 2022-10-22-daily 2022-10-23-daily 2022-10-23-weekly 2022-10-24-daily 2022-10-25-daily 2022-10-26-daily 2022-10-27-daily 2022-10-28-daily] MigrationType:{FSType:BTRFS Features:[migration_header header_subvolumes header_subvolume_uuids]} TrackProgress:true MultiSync:true FinalSync:false Data:<nil> ContentType: AllowInconsistent:false Refresh:true Info:0xc0003965a0 VolumeOnly:false}" instance=jitsi project=default version=1
INFO   [2022-10-28T12:06:42+01:00] Received migration index header response      args="&{IndexHeaderVersion:1 Name:jitsi Snapshots:[2022-09-01-monthly 2022-10-01-monthly 2022-10-02-weekly 2022-10-09-weekly 2022-10-16-weekly 2022-10-22-daily 2022-10-23-daily 2022-10-23-weekly 2022-10-24-daily 2022-10-25-daily 2022-10-26-daily 2022-10-27-daily 2022-10-28-daily] MigrationType:{FSType:BTRFS Features:[migration_header header_subvolumes header_subvolume_uuids]} TrackProgress:true MultiSync:true FinalSync:false Data:<nil> ContentType: AllowInconsistent:false Refresh:true Info:0xc0003965a0 VolumeOnly:false}" instance=jitsi project=default response="{StatusCode:200 Error: Refresh:0xc000ea1e5b}" version=1
DEBUG  [2022-10-28T12:07:01+01:00] Sent migration meta data header               driver=btrfs name=jitsi pool=srv
DEBUG  [2022-10-28T12:07:01+01:00] Received BTRFS migration meta data header     driver=btrfs name=jitsi pool=srv
DEBUG  [2022-10-28T12:07:01+01:00] Sending subvolume                             driver=btrfs name=jitsi/2022-09-01-monthly parent= path=/ pool=srv source=/var/snap/lxd/common/lxd/storage-pools/srv/containers-snapshots/jitsi/2022-09-01-monthly
INFO   [2022-10-28T12:07:32+01:00] Migration channels disconnected on source     instance=jitsi project="{{map[features.images:true features.networks:true features.profiles:true features.storage.buckets:true features.storage.volumes:true] Default LXD project} default []}"
DEBUG  [2022-10-28T12:07:32+01:00] Failure for operation                         class=websocket description="Migrating instance" err="Failed sending volume jitsi/2022-09-01-monthly:/: Btrfs send failed: [signal: killed write unix /var/snap/lxd/common/lxd/unix.socket->@: write: broken pipe] (At subvol /var/snap/lxd/common/lxd/storage-pools/srv/containers-snapshots/jitsi/2022-09-01-monthly\n)" operation=e983a5e6-7901-427a-9ca8-db0800d34479 project=default
ERROR  [2022-10-28T12:07:32+01:00] Migration failed on source                    err="Failed sending volume jitsi/2022-09-01-monthly:/: Btrfs send failed: [signal: killed write unix /var/snap/lxd/common/lxd/unix.socket->@: write: broken pipe] (At subvol /var/snap/lxd/common/lxd/storage-pools/srv/containers-snapshots/jitsi/2022-09-01-monthly\n)" instance=jitsi project="{{map[features.images:true features.networks:true features.profiles:true features.storage.buckets:true features.storage.volumes:true] Default LXD project} default []}"
DEBUG  [2022-10-28T12:07:32+01:00] MigrateInstance finished                      args="&{IndexHeaderVersion:1 Name:jitsi Snapshots:[2022-09-01-monthly 2022-10-01-monthly 2022-10-02-weekly 2022-10-09-weekly 2022-10-16-weekly 2022-10-22-daily 2022-10-23-daily 2022-10-23-weekly 2022-10-24-daily 2022-10-25-daily 2022-10-26-daily 2022-10-27-daily 2022-10-28-daily] MigrationType:{FSType:BTRFS Features:[migration_header header_subvolumes header_subvolume_uuids]} TrackProgress:true MultiSync:true FinalSync:false Data:<nil> ContentType: AllowInconsistent:false Refresh:true Info:0xc0003965a0 VolumeOnly:false}" instance=jitsi project=default
DEBUG  [2022-10-28T12:07:32+01:00] Event listener server handler stopped         listener=a4972008-8e31-4e1e-9104-d212d812dc93 local=/var/snap/lxd/common/lxd/unix.socket remote=@

Server B - The receiving server (I’ve removed the public IP, hopefully there’s nothing else confidential)

DEBUG  [2022-10-28T12:06:40+01:00] Handling API request                          ip="<SERVERB_IP_ADDRESS>:18866" method=GET protocol=tls url=/1.0 username=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a
DEBUG  [2022-10-28T12:06:40+01:00] Matched trusted cert                          fingerprint=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a subject="CN=root@servera,O=linuxcontainers.org"
DEBUG  [2022-10-28T12:06:40+01:00] Matched trusted cert                          fingerprint=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a subject="CN=root@servera,O=linuxcontainers.org"
DEBUG  [2022-10-28T12:06:40+01:00] Matched trusted cert                          fingerprint=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a subject="CN=root@servera,O=linuxcontainers.org"
DEBUG  [2022-10-28T12:06:40+01:00] Handling API request                          ip="<SERVERB_IP_ADDRESS>:20143" method=GET protocol=tls url=/1.0/events username=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a
DEBUG  [2022-10-28T12:06:40+01:00] Event listener server handler started         id=e6396189-9209-4da6-81ec-19e00001e7dc local="192.168.0.254:8443" remote="<SERVERB_IP_ADDRESS>:20143"
DEBUG  [2022-10-28T12:06:40+01:00] Responding to instance create
DEBUG  [2022-10-28T12:06:40+01:00] Matched trusted cert                          fingerprint=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a subject="CN=root@servera,O=linuxcontainers.org"
DEBUG  [2022-10-28T12:06:40+01:00] Handling API request                          ip="<SERVERB_IP_ADDRESS>:38918" method=POST protocol=tls url=/1.0/instances username=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a
DEBUG  [2022-10-28T12:06:40+01:00] Instance operation lock created               action=create instance=unifi project=default reusable=false
DEBUG  [2022-10-28T12:06:40+01:00] Started operation                             class=websocket description="Creating instance" operation=8e0ea020-7fb9-48e8-9f03-dfe9829baf6e project=default
DEBUG  [2022-10-28T12:06:40+01:00] New operation                                 class=websocket description="Creating instance" operation=8e0ea020-7fb9-48e8-9f03-dfe9829baf6e project=default
DEBUG  [2022-10-28T12:06:40+01:00] Instance operation lock finished              action=create err="<nil>" instance=unifi project=default reusable=false
INFO   [2022-10-28T12:06:40+01:00] Waiting for migration channel connections on target  instance=unifi project="{{map[features.images:true features.networks:true features.profiles:true features.storage.buckets:true features.storage.volumes:true] Default LXD project} default []}" push=true
DEBUG  [2022-10-28T12:06:40+01:00] Connecting to operation                       class=websocket description="Creating instance" operation=8e0ea020-7fb9-48e8-9f03-dfe9829baf6e project=default
DEBUG  [2022-10-28T12:06:40+01:00] Handling API request                          ip="<SERVERB_IP_ADDRESS>:22601" method=GET protocol=tls url="/1.0/operations/8e0ea020-7fb9-48e8-9f03-dfe9829baf6e/websocket?secret=ebf0a9ed09a6249096d64fa3ad4f78a2937befb0f854d7a7d8b340965a8f39f3" username=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a
DEBUG  [2022-10-28T12:06:40+01:00] Matched trusted cert                          fingerprint=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a subject="CN=root@servera,O=linuxcontainers.org"
DEBUG  [2022-10-28T12:06:40+01:00] Connected to operation                        class=websocket description="Creating instance" operation=8e0ea020-7fb9-48e8-9f03-dfe9829baf6e project=default
DEBUG  [2022-10-28T12:06:41+01:00] Connecting to operation                       class=websocket description="Creating instance" operation=8e0ea020-7fb9-48e8-9f03-dfe9829baf6e project=default
DEBUG  [2022-10-28T12:06:41+01:00] Matched trusted cert                          fingerprint=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a subject="CN=root@servera,O=linuxcontainers.org"
DEBUG  [2022-10-28T12:06:41+01:00] Connected to operation                        class=websocket description="Creating instance" operation=8e0ea020-7fb9-48e8-9f03-dfe9829baf6e project=default
DEBUG  [2022-10-28T12:06:41+01:00] Handling API request                          ip="<SERVERB_IP_ADDRESS>:5373" method=GET protocol=tls url="/1.0/operations/8e0ea020-7fb9-48e8-9f03-dfe9829baf6e/websocket?secret=0923d57c74dc403cf0b829f2d48de8f6b1eb06a371bb37676a65880739be73f1" username=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a
INFO   [2022-10-28T12:06:41+01:00] Migration channels connected on target        instance=unifi project="{{map[features.images:true features.networks:true features.profiles:true features.storage.buckets:true features.storage.volumes:true] Default LXD project} default []}" push=true
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock created               action=delete instance=unifi/2022-09-01-monthly project=default reusable=false
INFO   [2022-10-28T12:06:41+01:00] Deleting container                            created="2022-09-01 00:16:56 +0100 +0100" ephemeral=false instance=unifi/2022-09-01-monthly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Handling API request                          ip="<SERVERB_IP_ADDRESS>:39862" method=GET protocol=tls url=/1.0/operations/8e0ea020-7fb9-48e8-9f03-dfe9829baf6e username=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a
DEBUG  [2022-10-28T12:06:41+01:00] Matched trusted cert                          fingerprint=0db4e918cb21dc74ff664b1cac243d8c3dffe1a7432263f4442c218a06ecb32a subject="CN=root@servera,O=linuxcontainers.org"
DEBUG  [2022-10-28T12:06:41+01:00] Deleting instance snapshot volume             instance=unifi/2022-09-01-monthly project=default snapshotName=2022-09-01-monthly volName=unifi
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot started                instance=unifi/2022-09-01-monthly project=default
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot finished               instance=unifi/2022-09-01-monthly project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile started              instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile finished             instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock finished              action=delete err="<nil>" instance=unifi/2022-09-01-monthly project=default reusable=false
INFO   [2022-10-28T12:06:41+01:00] Deleted container                             created="2022-09-01 00:16:56 +0100 +0100" ephemeral=false instance=unifi/2022-09-01-monthly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
INFO   [2022-10-28T12:06:41+01:00] Deleting container                            created="2022-10-01 00:16:57 +0100 +0100" ephemeral=false instance=unifi/2022-10-01-monthly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock created               action=delete instance=unifi/2022-10-01-monthly project=default reusable=false
DEBUG  [2022-10-28T12:06:41+01:00] Deleting instance snapshot volume             instance=unifi/2022-10-01-monthly project=default snapshotName=2022-10-01-monthly volName=unifi
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot started                instance=unifi/2022-10-01-monthly project=default
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot finished               instance=unifi/2022-10-01-monthly project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile started              instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile finished             instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock finished              action=delete err="<nil>" instance=unifi/2022-10-01-monthly project=default reusable=false
INFO   [2022-10-28T12:06:41+01:00] Deleted container                             created="2022-10-01 00:16:57 +0100 +0100" ephemeral=false instance=unifi/2022-10-01-monthly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
INFO   [2022-10-28T12:06:41+01:00] Deleting container                            created="2022-10-02 00:16:58 +0100 +0100" ephemeral=false instance=unifi/2022-10-02-weekly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock created               action=delete instance=unifi/2022-10-02-weekly project=default reusable=false
DEBUG  [2022-10-28T12:06:41+01:00] Deleting instance snapshot volume             instance=unifi/2022-10-02-weekly project=default snapshotName=2022-10-02-weekly volName=unifi
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot started                instance=unifi/2022-10-02-weekly project=default
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot finished               instance=unifi/2022-10-02-weekly project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile started              instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile finished             instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock created               action=delete instance=unifi/2022-10-09-weekly project=default reusable=false
INFO   [2022-10-28T12:06:41+01:00] Deleting container                            created="2022-10-09 00:16:59 +0100 +0100" ephemeral=false instance=unifi/2022-10-09-weekly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
INFO   [2022-10-28T12:06:41+01:00] Deleted container                             created="2022-10-02 00:16:58 +0100 +0100" ephemeral=false instance=unifi/2022-10-02-weekly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock finished              action=delete err="<nil>" instance=unifi/2022-10-02-weekly project=default reusable=false
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot started                instance=unifi/2022-10-09-weekly project=default
DEBUG  [2022-10-28T12:06:41+01:00] Deleting instance snapshot volume             instance=unifi/2022-10-09-weekly project=default snapshotName=2022-10-09-weekly volName=unifi
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot finished               instance=unifi/2022-10-09-weekly project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile started              instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile finished             instance=unifi project=default
INFO   [2022-10-28T12:06:41+01:00] Deleted container                             created="2022-10-09 00:16:59 +0100 +0100" ephemeral=false instance=unifi/2022-10-09-weekly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock created               action=delete instance=unifi/2022-10-16-weekly project=default reusable=false
INFO   [2022-10-28T12:06:41+01:00] Deleting container                            created="2022-10-16 00:17:04 +0100 +0100" ephemeral=false instance=unifi/2022-10-16-weekly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock finished              action=delete err="<nil>" instance=unifi/2022-10-09-weekly project=default reusable=false
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot started                instance=unifi/2022-10-16-weekly project=default
DEBUG  [2022-10-28T12:06:41+01:00] Deleting instance snapshot volume             instance=unifi/2022-10-16-weekly project=default snapshotName=2022-10-16-weekly volName=unifi
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot finished               instance=unifi/2022-10-16-weekly project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile started              instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile finished             instance=unifi project=default
INFO   [2022-10-28T12:06:41+01:00] Deleted container                             created="2022-10-16 00:17:04 +0100 +0100" ephemeral=false instance=unifi/2022-10-16-weekly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock created               action=delete instance=unifi/2022-10-22-daily project=default reusable=false
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock finished              action=delete err="<nil>" instance=unifi/2022-10-16-weekly project=default reusable=false
INFO   [2022-10-28T12:06:41+01:00] Deleting container                            created="2022-10-22 00:16:41 +0100 +0100" ephemeral=false instance=unifi/2022-10-22-daily instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Deleting instance snapshot volume             instance=unifi/2022-10-22-daily project=default snapshotName=2022-10-22-daily volName=unifi
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot started                instance=unifi/2022-10-22-daily project=default
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot finished               instance=unifi/2022-10-22-daily project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile started              instance=unifi project=default
INFO   [2022-10-28T12:06:41+01:00] Deleted container                             created="2022-10-22 00:16:41 +0100 +0100" ephemeral=false instance=unifi/2022-10-22-daily instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile finished             instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock finished              action=delete err="<nil>" instance=unifi/2022-10-22-daily project=default reusable=false
INFO   [2022-10-28T12:06:41+01:00] Deleting container                            created="2022-10-23 00:17:09 +0100 +0100" ephemeral=false instance=unifi/2022-10-23-daily instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock created               action=delete instance=unifi/2022-10-23-daily project=default reusable=false
DEBUG  [2022-10-28T12:06:41+01:00] Deleting instance snapshot volume             instance=unifi/2022-10-23-daily project=default snapshotName=2022-10-23-daily volName=unifi
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot started                instance=unifi/2022-10-23-daily project=default
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot finished               instance=unifi/2022-10-23-daily project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile started              instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile finished             instance=unifi project=default
INFO   [2022-10-28T12:06:41+01:00] Deleted container                             created="2022-10-23 00:17:09 +0100 +0100" ephemeral=false instance=unifi/2022-10-23-daily instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock created               action=delete instance=unifi/2022-10-23-weekly project=default reusable=false
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock finished              action=delete err="<nil>" instance=unifi/2022-10-23-daily project=default reusable=false
INFO   [2022-10-28T12:06:41+01:00] Deleting container                            created="2022-10-23 00:17:13 +0100 +0100" ephemeral=false instance=unifi/2022-10-23-weekly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot started                instance=unifi/2022-10-23-weekly project=default
DEBUG  [2022-10-28T12:06:41+01:00] Deleting instance snapshot volume             instance=unifi/2022-10-23-weekly project=default snapshotName=2022-10-23-weekly volName=unifi
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot finished               instance=unifi/2022-10-23-weekly project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile started              instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile finished             instance=unifi project=default
INFO   [2022-10-28T12:06:41+01:00] Deleted container                             created="2022-10-23 00:17:13 +0100 +0100" ephemeral=false instance=unifi/2022-10-23-weekly instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock finished              action=delete err="<nil>" instance=unifi/2022-10-23-weekly project=default reusable=false
INFO   [2022-10-28T12:06:41+01:00] Deleting container                            created="2022-10-24 00:19:37 +0100 +0100" ephemeral=false instance=unifi/2022-10-24-daily instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock created               action=delete instance=unifi/2022-10-24-daily project=default reusable=false
DEBUG  [2022-10-28T12:06:41+01:00] Deleting instance snapshot volume             instance=unifi/2022-10-24-daily project=default snapshotName=2022-10-24-daily volName=unifi
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot started                instance=unifi/2022-10-24-daily project=default
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot finished               instance=unifi/2022-10-24-daily project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile started              instance=unifi project=default
DEBUG  [2022-10-28T12:06:41+01:00] UpdateInstanceBackupFile finished             instance=unifi project=default
INFO   [2022-10-28T12:06:41+01:00] Deleted container                             created="2022-10-24 00:19:37 +0100 +0100" ephemeral=false instance=unifi/2022-10-24-daily instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock finished              action=delete err="<nil>" instance=unifi/2022-10-24-daily project=default reusable=false
INFO   [2022-10-28T12:06:41+01:00] Deleting container                            created="2022-10-25 00:16:32 +0100 +0100" ephemeral=false instance=unifi/2022-10-25-daily instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:41+01:00] Instance operation lock created               action=delete instance=unifi/2022-10-25-daily project=default reusable=false
DEBUG  [2022-10-28T12:06:41+01:00] Deleting instance snapshot volume             instance=unifi/2022-10-25-daily project=default snapshotName=2022-10-25-daily volName=unifi
DEBUG  [2022-10-28T12:06:41+01:00] DeleteInstanceSnapshot started                instance=unifi/2022-10-25-daily project=default
DEBUG  [2022-10-28T12:06:42+01:00] DeleteInstanceSnapshot finished               instance=unifi/2022-10-25-daily project=default
DEBUG  [2022-10-28T12:06:42+01:00] UpdateInstanceBackupFile started              instance=unifi project=default
INFO   [2022-10-28T12:06:42+01:00] Deleted container                             created="2022-10-25 00:16:32 +0100 +0100" ephemeral=false instance=unifi/2022-10-25-daily instanceType=container project=default used="0001-01-01 00:00:00 +0000 UTC"
DEBUG  [2022-10-28T12:06:42+01:00] UpdateInstanceBackupFile finished             instance=unifi project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock finished              action=delete err="<nil>" instance=unifi/2022-10-25-daily project=default reusable=false
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-09-01-monthly project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-09-01-monthly instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-09-01-monthly instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-01-monthly project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-01-monthly instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-01-monthly instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-02-weekly project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-02-weekly instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-02-weekly instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-09-weekly project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-09-weekly instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-09-weekly instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-16-weekly project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-16-weekly instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-16-weekly instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-22-daily project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-22-daily instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-22-daily instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-23-daily project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-23-daily instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-23-daily instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-23-weekly project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-23-weekly instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-23-weekly instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-24-daily project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-24-daily instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-24-daily instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-25-daily project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-25-daily instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-25-daily instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-26-daily project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-26-daily instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-26-daily instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-27-daily project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-27-daily instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-27-daily instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Instance operation lock created               action=create instance=unifi/2022-10-28-daily project=default reusable=false
INFO   [2022-10-28T12:06:42+01:00] Creating instance                             ephemeral=false instance=unifi/2022-10-28-daily instanceType=container project=default
INFO   [2022-10-28T12:06:42+01:00] Created container                             ephemeral=false instance=unifi/2022-10-28-daily instanceType=container project=default
DEBUG  [2022-10-28T12:06:42+01:00] Waiting for migration index header            args="{IndexHeaderVersion:1 Name:unifi Description: Config:map[] Snapshots:[2022-09-01-monthly 2022-10-01-monthly 2022-10-02-weekly 2022-10-09-weekly 2022-10-16-weekly 2022-10-22-daily 2022-10-23-daily 2022-10-23-weekly 2022-10-24-daily 2022-10-25-daily 2022-10-26-daily 2022-10-27-daily 2022-10-28-daily] MigrationType:{FSType:BTRFS Features:[migration_header header_subvolumes header_subvolume_uuids]} TrackProgress:true Refresh:true Live:true VolumeSize:0 ContentType: VolumeOnly:false}" instance=unifi project=default version=1
DEBUG  [2022-10-28T12:06:42+01:00] CreateInstanceFromMigration started           args="{IndexHeaderVersion:1 Name:unifi Description: Config:map[] Snapshots:[2022-09-01-monthly 2022-10-01-monthly 2022-10-02-weekly 2022-10-09-weekly 2022-10-16-weekly 2022-10-22-daily 2022-10-23-daily 2022-10-23-weekly 2022-10-24-daily 2022-10-25-daily 2022-10-26-daily 2022-10-27-daily 2022-10-28-daily] MigrationType:{FSType:BTRFS Features:[migration_header header_subvolumes header_subvolume_uuids]} TrackProgress:true Refresh:true Live:true VolumeSize:0 ContentType: VolumeOnly:false}" instance=unifi project=default
INFO   [2022-10-28T12:06:42+01:00] Received migration index header, sending response  args="{IndexHeaderVersion:1 Name:unifi Description: Config:map[] Snapshots:[2022-09-01-monthly 2022-10-01-monthly 2022-10-02-weekly 2022-10-09-weekly 2022-10-16-weekly 2022-10-22-daily 2022-10-23-daily 2022-10-23-weekly 2022-10-24-daily 2022-10-25-daily 2022-10-26-daily 2022-10-27-daily 2022-10-28-daily] MigrationType:{FSType:BTRFS Features:[migration_header header_subvolumes header_subvolume_uuids]} TrackProgress:true Refresh:true Live:true VolumeSize:0 ContentType: VolumeOnly:false}" instance=unifi project=default version=1
DEBUG  [2022-10-28T12:06:42+01:00] Sent migration index header response          args="{IndexHeaderVersion:1 Name:unifi Description: Config:map[] Snapshots:[2022-09-01-monthly 2022-10-01-monthly 2022-10-02-weekly 2022-10-09-weekly 2022-10-16-weekly 2022-10-22-daily 2022-10-23-daily 2022-10-23-weekly 2022-10-24-daily 2022-10-25-daily 2022-10-26-daily 2022-10-27-daily 2022-10-28-daily] MigrationType:{FSType:BTRFS Features:[migration_header header_subvolumes header_subvolume_uuids]} TrackProgress:true Refresh:true Live:true VolumeSize:0 ContentType: VolumeOnly:false}" instance=unifi project=default version=1
DEBUG  [2022-10-28T12:07:01+01:00] Received BTRFS migration meta data header     driver=btrfs name=unifi pool=default
DEBUG  [2022-10-28T12:07:01+01:00] Sent BTRFS migration meta data header         driver=btrfs header="{[{/ 2022-09-01-monthly false 5d2a0899-9860-9543-b0e6-514094809d01} {/ 2022-10-01-monthly false 14b32def-bc0b-6644-b9a6-ad2684bf17cd} {/ 2022-10-02-weekly false e0942a0d-fd4e-2c4c-8b14-3cd34e6ba05f} {/ 2022-10-09-weekly false 12f1b3af-c38f-ce4d-9612-30605e7c32f9} {/ 2022-10-16-weekly false 817c5405-0d2f-bf44-a4e3-62582b483a40} {/ 2022-10-22-daily false 3edde513-5dad-c941-ac93-7d1393858a08} {/ 2022-10-23-daily false 98c86388-1489-9d49-9e6f-000dea51b1c5} {/ 2022-10-23-weekly false f06be91b-d9c8-d84b-a771-fb48ebbd18ab} {/ 2022-10-24-daily false 8b18ce67-28f8-224e-87aa-536816db246d} {/ 2022-10-25-daily false 26ea40ce-76cd-4d46-961a-623a85260982} {/ 2022-10-26-daily false 17383f08-c386-124b-adc6-e9deb770d25f} {/ 2022-10-27-daily false 10c73eaa-c507-c046-9796-33efa57d5af7} {/ 2022-10-28-daily false ca3fec30-2bb8-1946-8c7c-9166ad34aefc} {/  false d9cc3710-0dca-9b4b-96ad-ab320010026a}]}" name=unifi pool=default
DEBUG  [2022-10-28T12:07:01+01:00] Receiving volume                              driver=btrfs name=unifi/2022-09-01-monthly path=/var/snap/lxd/common/lxd/storage-pools/default/containers-snapshots/unifi/2022-09-01-monthly pool=default receivePath=/var/snap/lxd/common/lxd/storage-pools/default/containers/migration.982773777/2022-09-01-monthly
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-09-01-monthly project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-01-monthly project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-02-weekly project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-09-weekly project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-16-weekly project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-22-daily project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-23-daily project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-23-weekly project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-24-daily project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-25-daily project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-26-daily project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-27-daily project=default reusable=false
DEBUG  [2022-10-28T12:07:12+01:00] Instance operation lock finished              action=create err="Instance \"create\" operation timed out after 30s" instance=unifi/2022-10-28-daily project=default reusable=false
INFO   [2022-10-28T12:07:32+01:00] Migration channels disconnected on target     instance=unifi project="{{map[features.images:true features.networks:true features.profiles:true features.storage.buckets:true features.storage.volumes:true] Default LXD project} default []}" push=true
DEBUG  [2022-10-28T12:07:32+01:00] Failure for operation                         class=websocket description="Creating instance" err="Error transferring instance data: Failed sending volume jitsi/2022-09-01-monthly:/: Btrfs send failed: [signal: killed write unix /var/snap/lxd/common/lxd/unix.socket->@: write: broken pipe] (At subvol /var/snap/lxd/common/lxd/storage-pools/srv/containers-snapshots/jitsi/2022-09-01-monthly\n)" operation=8e0ea020-7fb9-48e8-9f03-dfe9829baf6e project=default
DEBUG  [2022-10-28T12:07:32+01:00] Event listener server handler stopped         listener=e6396189-9209-4da6-81ec-19e00001e7dc local="192.168.0.254:8443" remote="<SERVERB_IP_ADDRESS>:20143"```

DanielBull · November 1, 2022, 8:48am

I’m guessing this is just affecting me then?

DanielBull · November 10, 2022, 2:38pm

I just upgraded both machines to 22.04
The issue is still present

tomp · November 14, 2022, 9:31am

Does this only happen when using --mode=relay?

DanielBull · November 14, 2022, 11:51am

I require mode relay for my setup.
Let me try setting up a local server and trying with an without relay.

DanielBull · November 14, 2022, 1:02pm

OK I deleted a container from serverb. Made a fresh copy locally by going from server A to my desktop. No issues with mode relay. Then tried to copy it from my desktop to severb with mode relay, same errors as when going direct from servera to serverb. So at least we know servera isn’t the problem.

I cant copy to serverb without mode relay as locally we are behind NAT.

Just trying mode=push now…

DanielBull · November 14, 2022, 1:13pm

–mode=push fails as well…

sudo lxc copy jitsi serverb:jitsi --storage=default --mode=push
Error: Failed instance migration: Failed sending volume jitsi/2022-10-30-weekly:/: Btrfs send failed: [signal: killed write tcp <LOCAL IP>:57824-><SERVERB_IP_ADDRESS>:8443: write: connection reset by peer] (At subvol /var/snap/lxd/common/lxd/storage-pools/default/containers-snapshots/jitsi/2022-10-30-weekly)

It seemed to get quite a way before failing though, same as with mode=relay (IE multiple GB)

tomp · November 14, 2022, 2:58pm

Are you running LXD 5.7 both servers and client?

tomp · November 14, 2022, 3:30pm

Can you try this custom LXD and LXC build on your new server (dont use this on any production systems). It has the recently added TCP timeouts for websockets removed.

https://www.tomp.uk/files/lxd.debug
https://www.tomp.uk/files/lxc.debug

Then side load these into the snap on both server and client systems using:

sudo mv lxd.debug /var/snap/lxd/common/lxd.debug
sudo mv lxc.debug /var/snap/lxd/common/lxc.debug
sudo systemctl reload snap.lxd.daemon

Then retry and see if that fixes it.

To remove the sideloaded binaries do:

rm /var/snap/lxd/common/lxd.debug /var/snap/lxd/common/lxc.debug
sudo systemctl reload snap.lxd.daemon

But be aware that because of DB schema changes in this latest build any servers you apply these binaries too will not be able to downgrade (and thus not start back up again) on the current latest/stable channel until LXD 5.8 is released.

DanielBull · November 14, 2022, 5:59pm

Yes both 5.7 snap packages both 22.04 now I’ve upgraded.

DanielBull · November 14, 2022, 6:01pm

OK thanks I’ll have to see what I can do, I can do it at this end but I don’t have a way to do it at the remote end.

tomp · November 15, 2022, 9:02am

I’ve added shared: Increase default TCP user timeout from 30 seconds to 2 minutes by tomponline · Pull Request #11117 · lxc/lxd · GitHub which should go into LXD 5.8, to see if this helps.

tomp · November 21, 2022, 10:06am

Please can you try LXD 5.8 in channel latest/candidate as this has these fixes applied also.

DanielBull · November 21, 2022, 10:21am

Hi Tom,
Has anything changed to 5.7?
The reason I ask is I did the following…

Deleted all the containers from server B
Removed all the broken migration BTRFS volumes (there were a LOT)
Recopied across all the containers

And I’ve not had a any errors doing the refresh for 2 days.
Sorry I didnt get to test your code, I could not find a way to do get a machine at the remote site suitable for testing on. I did try it just by using the new version locally against serverb but it didn’t make any difference I still got the errors. I think this is because they were triggered at the far end.

tomp · November 21, 2022, 10:22am

No, not that I know of.

More likely is that by deleting and recopying the I/O pattern changed that meant it didn’t cause slow responses triggering the timeout.

DanielBull · November 21, 2022, 10:36am

Hmm interesting. This is a 8 disk MD RAID10 setup, it shouldn’t have been slow but that does seem to make sense.