Update to 3.19 broke btrfs storage for snap lxd package

plaes · January 24, 2020, 7:53pm

Firstly, snap image on Debian 10 and after auto update to 3.19 something broke regarding the btrfs-backed storage:

$ lxc launch ubuntu:18.04
Creating the instance
Error: Failed instance creation: Create instance from image: Failed to run: btrfs subvolume create /var/snap/lxd/common/lxd/storage-pools/default/images/979ff60086ca9fb1c93d3131f8eca291820a524f0bd0b7d621a3c2f5f41ef185: ERROR: not a btrfs filesystem: /var/snap/lxd/common/lxd/storage-pools/default/images

BTRFS-backed storage has been configured, but seems like 3.19 somehow is not picking it up automatically:

$ lxc storage show default
config:
  source: /btrfs/lxc
  volatile.initial_source: /btrfs/lxc
description: ""
name: default
driver: btrfs
used_by:
- /1.0/containers/choice-lioness
- /1.0/containers/helping-puma
- /1.0/profiles/default
status: Created
locations:
- none

stgraber · January 24, 2020, 9:49pm

This is a bit odd indeed.
Could you do:

snap set lxd daemon.debug=true
systemctl reload snap.lxd.daemon
lxc info
cat /proc/$(cat /var/snap/lxd/common/lxd.pid)/mountinfo
lxc launch ubuntu:18.04
cat /var/snap/lxd/common/lxd/logs/lxd.log

This should capture quite a few more details that should be helpful to us.

plaes · January 25, 2020, 6:58am

Thanks for the ideas, firstly btrfs subvolumes:
$ btrfs subvol list /btrfs/:

ID 264 gen 1667 top level 5 path lxc
ID 265 gen 1667 top level 264 path lxc/containers
ID 266 gen 1668 top level 264 path lxc/containers-snapshots
ID 267 gen 1667 top level 264 path lxc/images
ID 268 gen 1668 top level 264 path lxc/custom
ID 269 gen 1668 top level 264 path lxc/custom-snapshots
ID 272 gen 245 top level 267 path lxc/images/979ff60086ca9fb1c93d3131f8eca291820a524f0bd0b7d621a3c2f5f41ef185
ID 274 gen 1661 top level 5 path libvirt-images
ID 275 gen 1669 top level 265 path lxc/containers/helping-puma
ID 276 gen 1669 top level 265 path lxc/containers/choice-lioness

Also, I don’t have fstab entry for lxc subvolume, previously it worked fine without.

Now, after setting daemon.debug=true and reloading snap.lxd.daemon, the output of lxc info:

config: {}                    
api_extensions:                        
  [...]
api_status: stable                                                                                                                                                                                                                  
api_version: "1.0"                                                                                                                                                                                                                  
auth: trusted
public: false
auth_methods:
- tls
environment:
  addresses: []
  architectures:
  - x86_64
  - i686
  certificate: |
    -----BEGIN CERTIFICATE-----
    [...]
    -----END CERTIFICATE-----
  certificate_fingerprint: [...]
  driver: lxc
  driver_version: 3.2.1
  kernel: Linux
  kernel_architecture: x86_64
  kernel_features:
    netnsid_getifaddrs: "false"
    seccomp_listener: "false"
    seccomp_listener_continue: "false"
    shiftfs: "false"
    uevent_injection: "true"
    unpriv_fscaps: "true"
  kernel_version: 4.19.0-6-amd64
  lxc_features:
    cgroup2: "false"
    mount_injection_file: "true"
    network_gateway_device_route: "true"
    network_ipvlan: "true"
    network_l2proxy: "true"
    network_phys_macvlan_mtu: "true"
    network_veth_router: "true"
    seccomp_notify: "true"
  project: default
  server: lxd
  server_clustered: false
  server_name: plaes-blade
  server_pid: 16075
  server_version: "3.19"
  storage: btrfs
  storage_version: "4.4"

Output of cat /proc/$(cat /var/snap/lxd/common/lxd.pid)/mountinfo:

222 312 8:1 / /var/lib/snapd/hostfs rw,relatime master:1 - ext4 /dev/sda1 rw,errors=remount-ro                                
228 222 0:21 / /var/lib/snapd/hostfs/run rw,nosuid,noexec,relatime master:5 - tmpfs tmpfs rw,size=19807580k,mode=755          
229 228 0:23 / /var/lib/snapd/hostfs/run/lock rw,nosuid,nodev,noexec,relatime master:6 - tmpfs tmpfs rw,size=5120k            
230 228 0:21 /snapd/ns /var/lib/snapd/hostfs/run/snapd/ns rw,nosuid,noexec,relatime - tmpfs tmpfs rw,size=19807580k,mode=755  
251 222 0:41 /home /var/lib/snapd/hostfs/home rw,relatime master:57 - btrfs /dev/sda3 rw,space_cache,subvolid=257,subvol=/home
252 222 0:41 / /var/lib/snapd/hostfs/btrfs rw,relatime master:59 - btrfs /dev/sda3 rw,space_cache,subvolid=5,subvol=/           
253 222 8:5 / /var/lib/snapd/hostfs/var rw,relatime master:61 - ext4 /dev/sda5 rw                                             
254 253 0:41 /libvirt-images /var/lib/snapd/hostfs/var/lib/libvirt/images rw,relatime master:65 - btrfs /dev/sda3 rw,space_cache,subvolid=274,subvol=/libvirt-images
255 222 8:6 / /var/lib/snapd/hostfs/tmp rw,relatime master:63 - ext4 /dev/sda6 rw                                               
257 222 7:0 / /var/lib/snapd/hostfs/snap/core/8268 ro,nodev,relatime master:69 - squashfs /dev/loop0 ro                          
264 221 7:0 / / ro,nodev,relatime master:69 - squashfs /dev/loop0 ro                                                             
265 264 0:6 / /dev rw,nosuid,relatime master:2 - devtmpfs udev rw,size=99021028k,nr_inodes=24755257,mode=755                     
266 265 0:20 / /dev/pts rw,nosuid,noexec,relatime master:3 - devpts devpts rw,gid=5,mode=620,ptmxmode=000                       
267 265 0:22 / /dev/shm rw,nosuid,nodev master:4 - tmpfs tmpfs rw                                                               
268 265 0:40 / /dev/hugepages rw,relatime master:26 - hugetlbfs hugetlbfs rw,pagesize=2M                                         
269 265 0:18 / /dev/mqueue rw,relatime master:27 - mqueue mqueue rw                                                                                        
271 264 0:41 /home /home rw,relatime master:57 - btrfs /dev/sda3 rw,space_cache,subvolid=257,subvol=/home                        
272 264 8:1 /root /root rw,relatime master:1 - ext4 /dev/sda1 rw,errors=remount-ro                                                               
273 264 0:4 / /proc rw,nosuid,nodev,noexec,relatime master:14 - proc proc rw                                                     
274 273 0:39 / /proc/sys/fs/binfmt_misc rw,relatime master:25 - autofs systemd-1 rw,fd=27,pgrp=1,timeout=0,minproto=5,maxproto=5,direct,pipe_ino=15976
275 264 0:19 / /sys rw,nosuid,nodev,noexec,relatime master:7 - sysfs sysfs rw                                                   
276 275 0:7 / /sys/kernel/security rw,nosuid,nodev,noexec,relatime master:8 - securityfs securityfs rw                          
277 275 0:24 / /sys/fs/cgroup ro,nosuid,nodev,noexec master:9 - tmpfs tmpfs ro,mode=755                                         
278 277 0:25 / /sys/fs/cgroup/unified rw,nosuid,nodev,noexec,relatime master:10 - cgroup2 cgroup2 rw                            
279 277 0:26 / /sys/fs/cgroup/systemd rw,nosuid,nodev,noexec,relatime master:11 - cgroup cgroup rw,xattr,name=systemd           
280 277 0:29 / /sys/fs/cgroup/cpu,cpuacct rw,nosuid,nodev,noexec,relatime master:15 - cgroup cgroup rw,cpu,cpuacct             
281 277 0:30 / /sys/fs/cgroup/net_cls,net_prio rw,nosuid,nodev,noexec,relatime master:16 - cgroup cgroup rw,net_cls,net_prio  
282 277 0:31 / /sys/fs/cgroup/freezer rw,nosuid,nodev,noexec,relatime master:17 - cgroup cgroup rw,freezer                     
283 277 0:32 / /sys/fs/cgroup/blkio rw,nosuid,nodev,noexec,relatime master:18 - cgroup cgroup rw,blkio                        
284 277 0:33 / /sys/fs/cgroup/cpuset rw,nosuid,nodev,noexec,relatime master:19 - cgroup cgroup rw,cpuset,clone_children       
285 277 0:34 / /sys/fs/cgroup/pids rw,nosuid,nodev,noexec,relatime master:20 - cgroup cgroup rw,pids                             
286 277 0:35 / /sys/fs/cgroup/devices rw,nosuid,nodev,noexec,relatime master:21 - cgroup cgroup rw,devices                       
287 277 0:36 / /sys/fs/cgroup/perf_event rw,nosuid,nodev,noexec,relatime master:22 - cgroup cgroup rw,perf_event                 
288 277 0:37 / /sys/fs/cgroup/rdma rw,nosuid,nodev,noexec,relatime master:23 - cgroup cgroup rw,rdma                             
289 277 0:38 / /sys/fs/cgroup/memory rw,nosuid,nodev,noexec,relatime master:24 - cgroup cgroup rw,memory                       
290 275 0:27 / /sys/fs/pstore rw,nosuid,nodev,noexec,relatime master:12 - pstore pstore rw                                     
291 275 0:28 / /sys/fs/bpf rw,nosuid,nodev,noexec,relatime master:13 - bpf bpf rw,mode=700                                     
292 275 0:8 / /sys/kernel/debug rw,relatime master:28 - debugfs debugfs rw                                                     
293 264 8:6 / /tmp rw,relatime master:63 - ext4 /dev/sda6 rw                                                                  
294 264 8:5 /snap /var/snap rw,relatime master:61 - ext4 /dev/sda5 rw                                                           
295 264 8:5 /lib/snapd /var/lib/snapd rw,relatime master:61 - ext4 /dev/sda5 rw                                                 
296 264 8:5 /tmp /var/tmp rw,relatime master:61 - ext4 /dev/sda5 rw                                                             
300 264 8:1 /usr/lib/modules /lib/modules rw,relatime master:1 - ext4 /dev/sda1 rw,errors=remount-ro                            
301 264 8:1 /usr/lib/firmware /lib/firmware rw,relatime master:1 - ext4 /dev/sda1 rw,errors=remount-ro                          
302 264 8:1 /usr/src /usr/src rw,relatime master:1 - ext4 /dev/sda1 rw,errors=remount-ro                                        
303 264 8:5 /log /var/log rw,relatime master:61 - ext4 /dev/sda5 rw                                                             
304 264 8:1 /media /media rw,relatime shared:1 - ext4 /dev/sda1 rw,errors=remount-ro                                            
306 264 8:1 /mnt /mnt rw,relatime master:1 - ext4 /dev/sda1 rw,errors=remount-ro
309 264 8:1 /snap /snap rw,relatime master:1 - ext4 /dev/sda1 rw,errors=remount-ro
311 309 7:0 / /snap/core/8268 ro,nodev,relatime master:69 - squashfs /dev/loop0 ro
312 295 8:5 /lib/snapd/hostfs /var/lib/snapd/hostfs rw,relatime - ext4 /dev/sda5 rw
223 293 8:6 /snap.lxd/tmp /tmp rw,relatime - ext4 /dev/sda6 rw
224 266 0:48 / /dev/pts rw,relatime - devpts devpts rw,gid=5,mode=620,ptmxmode=666
225 265 0:48 /ptmx /dev/ptmx rw,relatime - devpts devpts rw,gid=5,mode=620,ptmxmode=666
226 294 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
227 294 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
344 294 0:49 / /var/snap/lxd/common/shmounts rw,relatime shared:130 - tmpfs tmpfs rw,size=1024k,mode=711
326 264 7:1 /wrappers/kmod /bin/kmod ro,nodev,relatime - squashfs /dev/loop1 ro
298 264 8:1 /usr/share/ca-certificates /usr/share/ca-certificates rw,relatime master:1 - ext4 /dev/sda1 rw,errors=remount-ro
299 222 0:6 / /var/lib/snapd/hostfs/dev rw,nosuid,relatime master:2 - devtmpfs udev rw,size=99021028k,nr_inodes=24755257,mode=755
305 222 0:4 / /var/lib/snapd/hostfs/proc rw,nosuid,nodev,noexec,relatime master:14 - proc proc rw
307 222 0:19 / /var/lib/snapd/hostfs/sys rw,nosuid,nodev,noexec,relatime master:7 - sysfs sysfs rw
343 307 0:55 / /var/lib/snapd/hostfs/sys/fs/fuse/connections rw,relatime master:129 - fusectl fusectl rw
332 275 0:55 / /sys/fs/fuse/connections rw,relatime master:129 - fusectl fusectl rw
352 226 0:41 /lxc /var/snap/lxd/common/lxd/storage-pools/default rw,relatime shared:137 master:59 - btrfs /dev/sda3 rw,space_cache,subvolid=264,subvol=/lxc
454 274 0:65 / /proc/sys/fs/binfmt_misc rw,relatime master:138 - binfmt_misc binfmt_misc rw
440 228 0:71 / /var/lib/snapd/hostfs/run/user/1000 rw,nosuid,nodev,relatime master:142 - tmpfs tmpfs rw,size=19807576k,mode=700,uid=1000,gid=1000
1101 260 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
1102 324 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
1103 326 7:2 /wrappers/kmod /bin/kmod ro,nodev,relatime - squashfs /dev/loop2 ro
416 309 7:3 / /snap/lxd/13085 ro,nodev,relatime master:314 - squashfs /dev/loop3 ro
409 222 7:3 / /var/lib/snapd/hostfs/snap/lxd/13085 ro,nodev,relatime master:314 - squashfs /dev/loop3 ro
417 262 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
418 261 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
419 327 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
420 325 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
421 1103 7:3 /wrappers/kmod /bin/kmod ro,nodev,relatime master:314 - squashfs /dev/loop3 ro
767 309 7:4 / /snap/lxd/13098 ro,nodev,relatime master:67 - squashfs /dev/loop4 ro
124 222 7:4 / /var/lib/snapd/hostfs/snap/lxd/13098 ro,nodev,relatime master:67 - squashfs /dev/loop4 ro
1104 310 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
1107 297 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
1106 270 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
1105 263 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
1108 333 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
1111 331 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
1110 329 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
1109 328 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
1112 421 7:4 /wrappers/kmod /bin/kmod ro,nodev,relatime master:67 - squashfs /dev/loop4 ro
123 320 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
237 319 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
236 318 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
235 317 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
234 316 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
233 315 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
232 314 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
231 313 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
238 341 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
245 340 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
244 339 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
243 338 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
242 337 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
241 336 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
240 335 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
239 334 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
246 1112 7:4 /wrappers/kmod /bin/kmod ro,nodev,relatime master:67 - squashfs /dev/loop4 ro
258 344 0:53 / /var/snap/lxd/common/shmounts/lxcfs rw,nosuid,nodev,relatime shared:128 - fuse.lxcfs lxcfs rw,user_id=0,group_id=0,allow_other
259 123 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
320 1104 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
319 417 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
318 1101 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
317 226 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
316 418 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
315 1107 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
314 1106 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
313 1105 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
310 237 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
297 236 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
270 235 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
263 234 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
262 233 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
261 232 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
260 231 8:5 /snap/lxd/common/lxd/storage-pools /var/snap/lxd/common/lxd/storage-pools rw,relatime shared:126 - ext4 /dev/sda5 rw
321 238 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
341 1108 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
340 419 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
339 1102 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
338 227 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
337 420 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
336 1111 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
335 1110 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
334 1109 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
333 245 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
331 244 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
329 243 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
328 242 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
327 241 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
325 240 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
324 239 8:5 /snap/lxd/common/lxd/devices /var/snap/lxd/common/lxd/devices rw,relatime shared:127 master:61 - ext4 /dev/sda5 rw
342 246 7:4 /wrappers/kmod /bin/kmod ro,nodev,relatime master:67 - squashfs /dev/loop4 ro
247 264 8:1 /boot /boot rw,relatime master:1 - ext4 /dev/sda1 rw,errors=remount-ro
248 264 0:54 / /run rw,nosuid,nodev,relatime - tmpfs tmpfs rw,mode=755
249 264 0:51 / /etc rw,relatime - tmpfs tmpfs rw,mode=755
349 344 0:56 / /var/snap/lxd/common/shmounts/containers rw,relatime shared:131 - tmpfs tmpfs rw,size=100k,mode=711
350 294 0:63 / /var/snap/lxd/common/lxd/devlxd rw,relatime - tmpfs tmpfs rw,size=100k,mode=755

$ lxc launch ubuntu:18.04:

 Creating the instance
 Error: Failed instance creation: Create instance from image: Failed to run: btrfs subvolume create /var/snap/lxd/common/lxd/storage-pools/default/images/6b11d9656e44792ead7f6571fb69b8425a87a3e7ad5a222028e5c9daf97ed794: ERROR: not a btrfs filesystem: /var/snap/lxd/common/lxd/storage-pools/default/images

$ cat /var/snap/lxd/common/lxd/logs/lxd.log:

t=2020-01-25T08:44:05+0200 lvl=info msg="LXD 3.19 is starting in normal mode" path=/var/snap/lxd/common/lxd
t=2020-01-25T08:44:05+0200 lvl=info msg="Kernel uid/gid map:"    
t=2020-01-25T08:44:05+0200 lvl=info msg=" - u 0 0 4294967295"                                         
t=2020-01-25T08:44:05+0200 lvl=info msg=" - g 0 0 4294967295"                                     
t=2020-01-25T08:44:05+0200 lvl=info msg="Configured LXD uid/gid map:"                                                                                                                                                              
t=2020-01-25T08:44:05+0200 lvl=info msg=" - u 0 1000000 1000000000"                                                                                                                                                                
t=2020-01-25T08:44:05+0200 lvl=info msg=" - g 0 1000000 1000000000"                                                                                                                                                                
t=2020-01-25T08:44:05+0200 lvl=info msg="Kernel features:"                                                                                                                                                                         
t=2020-01-25T08:44:05+0200 lvl=info msg=" - netnsid-based network retrieval: no"
t=2020-01-25T08:44:05+0200 lvl=info msg=" - uevent injection: yes"                                                                                                                                                                 
t=2020-01-25T08:44:05+0200 lvl=info msg=" - seccomp listener: no"                                                                                                                                                                  
t=2020-01-25T08:44:05+0200 lvl=info msg=" - seccomp listener continue syscalls: no"
t=2020-01-25T08:44:05+0200 lvl=info msg=" - unprivileged file capabilities: yes"                                                                                                                                                   
t=2020-01-25T08:44:05+0200 lvl=info msg=" - cgroup layout: hybrid"                                                                                                                                                                 
t=2020-01-25T08:44:05+0200 lvl=warn msg=" - Couldn't find the CGroup memory swap accounting, swap limits will be ignored"                                                                                                          
t=2020-01-25T08:44:05+0200 lvl=info msg=" - shiftfs support: disabled"                                                                                                                                                             
t=2020-01-25T08:44:05+0200 lvl=info msg="Initializing local database"                                                                                                                                                              
t=2020-01-25T08:44:05+0200 lvl=dbug msg="Initializing database gateway"                                                                                                                                                            
t=2020-01-25T08:44:05+0200 lvl=dbug msg="Start database node" address= id=1                                                                                                                                                        
t=2020-01-25T08:44:05+0200 lvl=info msg="Starting /dev/lxd handler:"                                                                                                                                                               
t=2020-01-25T08:44:05+0200 lvl=info msg=" - binding devlxd socket" socket=/var/snap/lxd/common/lxd/devlxd/sock                                                                                                                     
t=2020-01-25T08:44:05+0200 lvl=info msg="REST API daemon:"                                                                                                                                                                         
t=2020-01-25T08:44:05+0200 lvl=info msg=" - binding Unix socket" inherited=true socket=/var/snap/lxd/common/lxd/unix.socket                                                                                                        
t=2020-01-25T08:44:05+0200 lvl=info msg="Initializing global database"                                                                                                                                                             
t=2020-01-25T08:44:05+0200 lvl=dbug msg="Dqlite: connected address=1 id=1 attempt=0"                                                                                                                                               
t=2020-01-25T08:44:05+0200 lvl=info msg="Initializing storage pools"           
t=2020-01-25T08:44:05+0200 lvl=dbug msg="Initializing and checking storage pool \"default\""
t=2020-01-25T08:44:05+0200 lvl=dbug msg="Mount started" driver=btrfs pool=default
t=2020-01-25T08:44:05+0200 lvl=dbug msg="Mount finished" driver=btrfs pool=default
t=2020-01-25T08:44:05+0200 lvl=info msg="Initializing networks"
t=2020-01-25T08:44:06+0200 lvl=dbug msg="New task Operation: 8fa04da1-8514-48af-849a-41180d37ba1c"
t=2020-01-25T08:44:06+0200 lvl=info msg="Pruning leftover image files"
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Started task operation: 8fa04da1-8514-48af-849a-41180d37ba1c"
t=2020-01-25T08:44:06+0200 lvl=info msg="Done pruning leftover image files"
t=2020-01-25T08:44:06+0200 lvl=info msg="Loading daemon configuration"
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Success for task operation: 8fa04da1-8514-48af-849a-41180d37ba1c"
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Initialized inotify with file descriptor 3"
t=2020-01-25T08:44:06+0200 lvl=dbug msg=Handling ip=@ method=GET url=/1.0 user=
t=2020-01-25T08:44:06+0200 lvl=dbug msg="New task Operation: e2bf4dbe-7fc0-4508-8c8b-f2afc81c4d78"
t=2020-01-25T08:44:06+0200 lvl=info msg="Pruning expired images"
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Started task operation: e2bf4dbe-7fc0-4508-8c8b-f2afc81c4d78"
t=2020-01-25T08:44:06+0200 lvl=info msg="Done pruning expired images"
t=2020-01-25T08:44:06+0200 lvl=dbug msg=Handling ip=@ method=GET url=/internal/ready user=
t=2020-01-25T08:44:06+0200 lvl=dbug msg="New task Operation: 9d125b35-73f2-48d3-8de2-b86926911082"                             
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Success for task operation: e2bf4dbe-7fc0-4508-8c8b-f2afc81c4d78"                                                                                                                          
t=2020-01-25T08:44:06+0200 lvl=info msg="Pruning expired container backups"                                                                                                                                                         
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Started task operation: 9d125b35-73f2-48d3-8de2-b86926911082"                                                                                                                              
t=2020-01-25T08:44:06+0200 lvl=info msg="Done pruning expired container backups"          
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Success for task operation: 9d125b35-73f2-48d3-8de2-b86926911082"
t=2020-01-25T08:44:06+0200 lvl=dbug msg="New task Operation: 1d8cad75-e5c5-406c-8fb9-dd7b75a2b985"         
t=2020-01-25T08:44:06+0200 lvl=info msg="Updating instance types"                                                                              
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Started task operation: 1d8cad75-e5c5-406c-8fb9-dd7b75a2b985"                          
t=2020-01-25T08:44:06+0200 lvl=dbug msg="New task Operation: ca44dead-ff1a-4bb6-b497-07829637d110"                                                                                                               
t=2020-01-25T08:44:06+0200 lvl=info msg="Updating images"                                                                                                                                                                           
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Started task operation: ca44dead-ff1a-4bb6-b497-07829637d110"                                                                                                                              
t=2020-01-25T08:44:06+0200 lvl=info msg="Done updating images"                                                                                                                                                                      
t=2020-01-25T08:44:06+0200 lvl=dbug msg="New task Operation: 9db24161-8481-4423-9236-b51b9b57212d"                                                                                                                                  
t=2020-01-25T08:44:06+0200 lvl=info msg="Expiring log files"                                                                                                                                                     
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Started task operation: 9db24161-8481-4423-9236-b51b9b57212d"                         
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Success for task operation: 9db24161-8481-4423-9236-b51b9b57212d"                                     
t=2020-01-25T08:44:06+0200 lvl=info msg="Done expiring log files"                                              
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Scheduler: network: veth7ef67aba has been added: updating network priorities"
t=2020-01-25T08:44:06+0200 lvl=info msg="Done updating instance types"                                                                    
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Scheduler: network: vethf92f3cf7 has been added: updating network priorities"                                              
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Processing image" alias=19.04 fp=371697337f961b5763f0f1df4710aeceed6b2a41b8b9ca0adf2262d829b4ae09 protocol=simplestreams server=https://cloud-images.ubuntu.com/releases
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Connecting to a remote simplestreams server"                                                                                                                                               
t=2020-01-25T08:44:06+0200 lvl=dbug msg="MountInstance started" driver=btrfs instance=choice-lioness pool=default project=default                                                                                                   
t=2020-01-25T08:44:06+0200 lvl=dbug msg="MountInstance finished" driver=btrfs instance=choice-lioness pool=default project=default
t=2020-01-25T08:44:06+0200 lvl=eror msg="Failed to start container 'choice-lioness': Common start logic: saving config file for the container failed"
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Scheduler: network: vethe67b9b62 has been added: updating network priorities"                                                        
t=2020-01-25T08:44:06+0200 lvl=dbug msg="Scheduler: network: veth65abf814 has been added: updating network priorities"
t=2020-01-25T08:44:06+0200 lvl=dbug msg="MountInstance started" driver=btrfs instance=helping-puma pool=default project=default                                              
t=2020-01-25T08:44:06+0200 lvl=dbug msg="MountInstance finished" driver=btrfs instance=helping-puma pool=default project=default                                                                                                    
t=2020-01-25T08:44:06+0200 lvl=eror msg="Failed to start container 'helping-puma': Common start logic: saving config file for the container failed"   
t=2020-01-25T08:44:06+0200 lvl=dbug msg=Handling ip=@ method=GET url=/1.0 user=                                                                                                                                                     
t=2020-01-25T08:44:06+0200 lvl=dbug msg=Handling ip=@ method=GET url=/internal/ready user=                                                                                                                                          
t=2020-01-25T08:44:07+0200 lvl=dbug msg=Handling ip=@ method=GET url=/1.0 user=                                                                                                                                                     
t=2020-01-25T08:44:07+0200 lvl=dbug msg=Handling ip=@ method=GET url=/1.0 user=
t=2020-01-25T08:44:08+0200 lvl=dbug msg="Image already exists in the db" image=371697337f961b5763f0f1df4710aeceed6b2a41b8b9ca0adf2262d829b4ae09
t=2020-01-25T08:44:08+0200 lvl=dbug msg="Already up to date" fp=371697337f961b5763f0f1df4710aeceed6b2a41b8b9ca0adf2262d829b4ae09
t=2020-01-25T08:44:08+0200 lvl=dbug msg="Processing image" alias=18.04 fp=6b11d9656e44792ead7f6571fb69b8425a87a3e7ad5a222028e5c9daf97ed794 protocol=simplestreams server=https://cloud-images.ubuntu.com/releases
t=2020-01-25T08:44:08+0200 lvl=dbug msg="Connecting to a remote simplestreams server"
t=2020-01-25T08:44:08+0200 lvl=dbug msg="Success for task operation: 1d8cad75-e5c5-406c-8fb9-dd7b75a2b985"
t=2020-01-25T08:44:08+0200 lvl=dbug msg="Image already exists in the db" image=6b11d9656e44792ead7f6571fb69b8425a87a3e7ad5a222028e5c9daf97ed794
t=2020-01-25T08:44:08+0200 lvl=dbug msg="Already up to date" fp=6b11d9656e44792ead7f6571fb69b8425a87a3e7ad5a222028e5c9daf97ed794
t=2020-01-25T08:44:08+0200 lvl=dbug msg="Processing image" alias=18.04 fp=979ff60086ca9fb1c93d3131f8eca291820a524f0bd0b7d621a3c2f5f41ef185 protocol=simplestreams server=https://cloud-images.ubuntu.com/releases
t=2020-01-25T08:44:08+0200 lvl=dbug msg="Connecting to a remote simplestreams server"
t=2020-01-25T08:44:09+0200 lvl=dbug msg="Image already exists in the db" image=6b11d9656e44792ead7f6571fb69b8425a87a3e7ad5a222028e5c9daf97ed794
t=2020-01-25T08:44:09+0200 lvl=dbug msg="Success for task operation: ca44dead-ff1a-4bb6-b497-07829637d110"
t=2020-01-25T08:50:42+0200 lvl=dbug msg=Handling ip=@ method=GET url=/1.0 user=
t=2020-01-25T08:50:42+0200 lvl=dbug msg=Handling ip=@ method=GET url=/1.0/events user=
t=2020-01-25T08:50:42+0200 lvl=dbug msg="New event listener: b42d2275-6903-41d3-a8e0-915b6bce53f3"
t=2020-01-25T08:50:42+0200 lvl=dbug msg=Handling ip=@ method=POST url=/1.0/instances user=
t=2020-01-25T08:50:42+0200 lvl=dbug msg="\n\t{\n\t\t\"architecture\": \"\",\n\t\t\"config\": {},\n\t\t\"devices\": {},\n\t\t\"ephemeral\": false,\n\t\t\"profiles\": null,\n\t\t\"stateful\": false,\n\t\t\"description\": \"\",\n\t
\t\"name\": \"\",\n\t\t\"source\": {\n\t\t\t\"type\": \"image\",\n\t\t\t\"certificate\": \"\",\n\t\t\t\"alias\": \"18.04\",\n\t\t\t\"server\": \"https://cloud-images.ubuntu.com/releases\",\n\t\t\t\"protocol\": \"simplestreams\",
\n\t\t\t\"mode\": \"pull\"\n\t\t},\n\t\t\"instance_type\": \"\",\n\t\t\"type\": \"container\"\n\t}"
t=2020-01-25T08:50:42+0200 lvl=dbug msg="Responding to container create"
t=2020-01-25T08:50:42+0200 lvl=dbug msg="Connecting to a remote simplestreams server"
t=2020-01-25T08:50:42+0200 lvl=dbug msg="No name provided, creating stable-collie"
t=2020-01-25T08:50:42+0200 lvl=dbug msg="New task Operation: 8f1c8df6-f960-45d7-887b-d73dc67686bf"
t=2020-01-25T08:50:42+0200 lvl=dbug msg="Started task operation: 8f1c8df6-f960-45d7-887b-d73dc67686bf"
t=2020-01-25T08:50:42+0200 lvl=dbug msg="Connecting to a remote simplestreams server"
t=2020-01-25T08:50:42+0200 lvl=dbug msg="\n\t{\n\t\t\"type\": \"async\",\n\t\t\"status\": \"Operation created\",\n\t\t\"status_code\": 100,\n\t\t\"operation\": \"/1.0/operations/8f1c8df6-f960-45d7-887b-d73dc67686bf\",\n\t\t\"err
or_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\": {\n\t\t\t\"id\": \"8f1c8df6-f960-45d7-887b-d73dc67686bf\",\n\t\t\t\"class\": \"task\",\n\t\t\t\"description\": \"Creating container\",\n\t\t\t\"created_at\": \"2020-01-25T08
:50:42.803309631+02:00\",\n\t\t\t\"updated_at\": \"2020-01-25T08:50:42.803309631+02:00\",\n\t\t\t\"status\": \"Running\",\n\t\t\t\"status_code\": 103,\n\t\t\t\"resources\": {\n\t\t\t\t\"containers\": [\n\t\t\t\t\t\"/1.0/containe
rs/stable-collie\"\n\t\t\t\t],\n\t\t\t\t\"instances\": [\n\t\t\t\t\t\"/1.0/instances/stable-collie\"\n\t\t\t\t]\n\t\t\t},\n\t\t\t\"metadata\": null,\n\t\t\t\"may_cancel\": false,\n\t\t\t\"err\": \"\",\n\t\t\t\"location\": \"none
\"\n\t\t}\n\t}"
t=2020-01-25T08:50:42+0200 lvl=dbug msg=Handling ip=@ method=GET url=/1.0/operations/8f1c8df6-f960-45d7-887b-d73dc67686bf user=
t=2020-01-25T08:50:43+0200 lvl=dbug msg="Image already exists in the db" image=6b11d9656e44792ead7f6571fb69b8425a87a3e7ad5a222028e5c9daf97ed794
t=2020-01-25T08:50:43+0200 lvl=info msg="Creating container" ephemeral=false name=stable-collie project=default
t=2020-01-25T08:50:43+0200 lvl=info msg="Created container" ephemeral=false name=stable-collie project=default
t=2020-01-25T08:50:43+0200 lvl=dbug msg="CreateInstanceFromImage started" driver=btrfs instance=stable-collie pool=default project=default
t=2020-01-25T08:50:43+0200 lvl=dbug msg="EnsureImage started" driver=btrfs fingerprint=6b11d9656e44792ead7f6571fb69b8425a87a3e7ad5a222028e5c9daf97ed794 pool=default
t=2020-01-25T08:50:43+0200 lvl=dbug msg="EnsureImage finished" driver=btrfs fingerprint=6b11d9656e44792ead7f6571fb69b8425a87a3e7ad5a222028e5c9daf97ed794 pool=default
t=2020-01-25T08:50:43+0200 lvl=dbug msg="DeleteInstance started" driver=btrfs instance=stable-collie pool=default project=default
t=2020-01-25T08:50:43+0200 lvl=dbug msg="Deleting instance volume" driver=btrfs instance=stable-collie pool=default project=default volName=stable-collie
t=2020-01-25T08:50:43+0200 lvl=dbug msg="DeleteInstance finished" driver=btrfs instance=stable-collie pool=default project=default
t=2020-01-25T08:50:43+0200 lvl=dbug msg="CreateInstanceFromImage finished" driver=btrfs instance=stable-collie pool=default project=default
t=2020-01-25T08:50:43+0200 lvl=info msg="Deleting container" created=2020-01-25T08:50:43+0200 ephemeral=false name=stable-collie project=default used=1970-01-01T03:00:00+0300
t=2020-01-25T08:50:43+0200 lvl=dbug msg="Database error: &errors.errorString{s:\"No such object\"}"
t=2020-01-25T08:50:43+0200 lvl=info msg="Deleted container" created=2020-01-25T08:50:43+0200 ephemeral=false name=stable-collie project=default used=1970-01-01T03:00:00+0300
t=2020-01-25T08:50:43+0200 lvl=dbug msg="Failure for task operation: 8f1c8df6-f960-45d7-887b-d73dc67686bf: Create instance from image: Failed to run: btrfs subvolume create /var/snap/lxd/common/lxd/storage-pools/default/images/6
b11d9656e44792ead7f6571fb69b8425a87a3e7ad5a222028e5c9daf97ed794: ERROR: not a btrfs filesystem: /var/snap/lxd/common/lxd/storage-pools/default/images"
t=2020-01-25T08:50:43+0200 lvl=dbug msg="Event listener finished: b42d2275-6903-41d3-a8e0-915b6bce53f3"
t=2020-01-25T08:50:43+0200 lvl=dbug msg="Disconnected event listener: b42d2275-6903-41d3-a8e0-915b6bce53f3"

stgraber · January 25, 2020, 10:38am

Did you try rebooting your system?

Your namespace appears quite polluted with mounts which is likely causing the content of the storage pool to be hidden away.

plaes · January 25, 2020, 7:01pm

Ok, thanks, reboot did the trick for containers

Now, when testing the new vm stuff using the sample in 3.19 announcement, I ran into following:

Error: Failed instance creation: Create instance from image: Failed to run: btrfs subvolume snapshot /var/snap/lxd/common/lxd/storage-pools/default/images/5cba5a1288273a5c49056c8966595516a2d874ec6fa9bf7ca796399d0daeee9d /var/snap/lxd/common/lxd/storage-pools/default/virtual-machines/v1: ERROR: can't access '/var/snap/lxd/common/lxd/storage-pools/default/virtual-machines': No such file or directory

I just removed everything and reran the lxd init again, so both containers and virtual machines work now…

stgraber · January 26, 2020, 11:29am

Yeah, the hidden mount would have caused the migration logic that creates virtual-machines as a directory to apply to the wrong path, it didn’t fail as the path existed but then when fixing it and getting the right thing mounted, the directory wasn’t around anymore causing the issue.

It would have been an easy fix to get into the mount namespace and create that directory but re-installing works too

plaes · January 26, 2020, 1:02pm

Fortunately it is just a newly set up server, not full-blown production setup.

I suspect that there are some bugs when lxc storage is btrfs on a subvolume, instead of a dedicated block device.

plaes · January 26, 2020, 7:28pm

@stgraber Ugh… todays stable update broke my setup again

$ snap changes
[...]
13   Done    yesterday at 22:06 EET  yesterday at 22:06 EET  Install "lxd" snap
14   Done    today at 21:13 EET      today at 21:14 EET      Auto-refresh snap "lxd"

$ lxc launch ubuntu:18.04
Creating the instance
Error: Failed instance creation: Create instance from image: Failed to run: btrfs subvolume create /var/snap/lxd/common/lxd/storage-pools/default/images/979ff60086ca9fb1c93d3131f8eca291820a524f0bd0b7d621a3c2f5f41ef185: ERROR: can't access '/var/snap/lxd/common/lxd/storage-pools/default/images': No such file or directory

Rebooting the server got things going again, but… it’s not a long term solution

stgraber · January 27, 2020, 9:16am

Can you show cat /proc/self/mountinfo and journalctl -u snap.lxd.daemon -n 300?

plaes · January 27, 2020, 9:56am

Ok, after reboot things were fixed, but once again lxd packages was auto-updated by snap and this broke existing setup.

$ snap changes
...
16   Done    today at 03:05 EET      today at 03:05 EET      Auto-refresh snap "lxd"

$ lxc launch ubuntu:18.04
Creating the instance
Error: Failed instance creation: Create instance from image: Failed to run: btrfs subvolume create /var/snap/lxd/common/lxd/storage-pools/default/images/979ff60086ca9fb1c93d3131f8eca291820a524f0bd0b7d621a3c2f5f41ef185: ERROR: can't access '/var/snap/lxd/common/lxd/storage-pools/default/images': No such file or directory

$ cat /proc/self/mountinfo 
20 25 0:19 / /sys rw,nosuid,nodev,noexec,relatime shared:7 - sysfs sysfs rw
21 25 0:4 / /proc rw,nosuid,nodev,noexec,relatime shared:14 - proc proc rw
22 25 0:6 / /dev rw,nosuid,relatime shared:2 - devtmpfs udev rw,size=99020984k,nr_inodes=24755246,mode=755
23 22 0:20 / /dev/pts rw,nosuid,noexec,relatime shared:3 - devpts devpts rw,gid=5,mode=620,ptmxmode=000
24 25 0:21 / /run rw,nosuid,noexec,relatime shared:5 - tmpfs tmpfs rw,size=19807572k,mode=755
25 0 8:1 / / rw,relatime shared:1 - ext4 /dev/sda1 rw,errors=remount-ro
26 20 0:7 / /sys/kernel/security rw,nosuid,nodev,noexec,relatime shared:8 - securityfs securityfs rw
27 22 0:22 / /dev/shm rw,nosuid,nodev shared:4 - tmpfs tmpfs rw
28 24 0:23 / /run/lock rw,nosuid,nodev,noexec,relatime shared:6 - tmpfs tmpfs rw,size=5120k
29 20 0:24 / /sys/fs/cgroup ro,nosuid,nodev,noexec shared:9 - tmpfs tmpfs ro,mode=755
30 29 0:25 / /sys/fs/cgroup/unified rw,nosuid,nodev,noexec,relatime shared:10 - cgroup2 cgroup2 rw
31 29 0:26 / /sys/fs/cgroup/systemd rw,nosuid,nodev,noexec,relatime shared:11 - cgroup cgroup rw,xattr,name=systemd
32 20 0:27 / /sys/fs/pstore rw,nosuid,nodev,noexec,relatime shared:12 - pstore pstore rw
33 20 0:28 / /sys/fs/bpf rw,nosuid,nodev,noexec,relatime shared:13 - bpf bpf rw,mode=700
34 29 0:29 / /sys/fs/cgroup/net_cls,net_prio rw,nosuid,nodev,noexec,relatime shared:15 - cgroup cgroup rw,net_cls,net_prio
35 29 0:30 / /sys/fs/cgroup/cpu,cpuacct rw,nosuid,nodev,noexec,relatime shared:16 - cgroup cgroup rw,cpu,cpuacct
36 29 0:31 / /sys/fs/cgroup/memory rw,nosuid,nodev,noexec,relatime shared:17 - cgroup cgroup rw,memory
37 29 0:32 / /sys/fs/cgroup/devices rw,nosuid,nodev,noexec,relatime shared:18 - cgroup cgroup rw,devices
38 29 0:33 / /sys/fs/cgroup/pids rw,nosuid,nodev,noexec,relatime shared:19 - cgroup cgroup rw,pids
39 29 0:34 / /sys/fs/cgroup/blkio rw,nosuid,nodev,noexec,relatime shared:20 - cgroup cgroup rw,blkio
40 29 0:35 / /sys/fs/cgroup/cpuset rw,nosuid,nodev,noexec,relatime shared:21 - cgroup cgroup rw,cpuset,clone_children
41 29 0:36 / /sys/fs/cgroup/perf_event rw,nosuid,nodev,noexec,relatime shared:22 - cgroup cgroup rw,perf_event
42 29 0:37 / /sys/fs/cgroup/freezer rw,nosuid,nodev,noexec,relatime shared:23 - cgroup cgroup rw,freezer
43 29 0:38 / /sys/fs/cgroup/rdma rw,nosuid,nodev,noexec,relatime shared:24 - cgroup cgroup rw,rdma
44 21 0:39 / /proc/sys/fs/binfmt_misc rw,relatime shared:25 - autofs systemd-1 rw,fd=31,pgrp=1,timeout=0,minproto=5,maxproto=5,direct,pipe_ino=3671
45 22 0:18 / /dev/mqueue rw,relatime shared:26 - mqueue mqueue rw
46 22 0:40 / /dev/hugepages rw,relatime shared:27 - hugetlbfs hugetlbfs rw,pagesize=2M
47 20 0:8 / /sys/kernel/debug rw,relatime shared:28 - debugfs debugfs rw
110 25 8:6 / /tmp rw,relatime shared:57 - ext4 /dev/sda6 rw
111 25 8:5 / /var rw,relatime shared:59 - ext4 /dev/sda5 rw
108 25 0:42 / /btrfs rw,relatime shared:61 - btrfs /dev/sda3 rw,space_cache,user_subvol_rm_allowed,subvolid=5,subvol=/
106 25 0:42 /home /home rw,noatime shared:63 - btrfs /dev/sda3 rw,space_cache,user_subvol_rm_allowed,subvolid=257,subvol=/home
107 25 7:0 / /snap/core/8268 ro,nodev,relatime shared:67 - squashfs /dev/loop0 ro
124 25 7:2 / /snap/lxd/13129 ro,nodev,relatime shared:69 - squashfs /dev/loop2 ro
216 24 0:21 /snapd/ns /run/snapd/ns rw,nosuid,noexec,relatime - tmpfs tmpfs rw,size=19807572k,mode=755
226 216 0:3 mnt:[4026532481] /run/snapd/ns/lxd.mnt rw - nsfs nsfs rw
334 111 0:48 / /var/snap/lxd/common/ns rw,relatime - tmpfs tmpfs rw,size=1024k,mode=700
343 334 0:3 mnt:[4026532482] /var/snap/lxd/common/ns/shmounts rw - nsfs nsfs rw
326 334 0:3 mnt:[4026532481] /var/snap/lxd/common/ns/mntns rw - nsfs nsfs rw
331 20 0:54 / /sys/fs/fuse/connections rw,relatime shared:129 - fusectl fusectl rw
540 44 0:64 / /proc/sys/fs/binfmt_misc rw,relatime shared:141 - binfmt_misc binfmt_misc rw
354 25 7:3 / /snap/lxd/13140 ro,nodev,relatime shared:138 - squashfs /dev/loop3 ro
119 24 0:50 / /run/user/1000 rw,nosuid,nodev,relatime shared:65 - tmpfs tmpfs rw,size=19807568k,mode=700,uid=1000,gid=1000

And lxd daemon logs:

-- Logs begin at Sun 2020-01-26 21:35:09 EET, end at Mon 2020-01-27 11:53:41 EET. --
Jan 26 21:35:15 plaes-blade systemd[1]: Started Service for snap application lxd.daemon.
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: => Preparing the system (13129)
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: ==> Loading snap configuration
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: ==> Setting up mntns symlink (mnt:[4026532481])
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: ==> Setting up mount propagation on /var/snap/lxd/common/lxd/storage-pools
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: ==> Setting up mount propagation on /var/snap/lxd/common/lxd/devices
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: ==> Setting up persistent shmounts path
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: ====> Making LXD shmounts use the persistent path
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: ====> Making LXCFS use the persistent path
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: ==> Setting up kmod wrapper
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: ==> Preparing /boot
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: ==> Preparing a clean copy of /run
Jan 26 21:35:15 plaes-blade lxd.daemon[1015]: ==> Preparing a clean copy of /etc
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: ==> Setting up ceph configuration
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: ==> Setting up LVM configuration
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: ==> Rotating logs
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: ==> Escaping the systemd cgroups
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: ====> Detected cgroup V1
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: ==> Escaping the systemd process resource limits
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: ==> Increasing the number of inotify user instances
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: ==> Enabling unprivileged containers kernel support
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: ==> Disabling shiftfs on this kernel (auto)
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: ==> Detected kernel with partial AppArmor support
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: => Starting LXCFS
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: => Starting LXD
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: mount namespace: 5
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: hierarchies:
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:   0: fd:   6: rdma
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:   1: fd:   7: freezer
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:   2: fd:   8: perf_event
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:   3: fd:   9: cpuset
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:   4: fd:  10: blkio
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:   5: fd:  11: pids
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:   6: fd:  12: devices
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:   7: fd:  13: memory
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:   8: fd:  14: cpu,cpuacct
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:   9: fd:  15: net_cls,net_prio
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:  10: fd:  16: name=systemd
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]:  11: fd:  17: unified
Jan 26 21:35:16 plaes-blade lxd.daemon[1015]: t=2020-01-26T21:35:16+0200 lvl=warn msg=" - Couldn't find the CGroup memory swap accounting, swap limits will be ignored"
Jan 26 21:35:19 plaes-blade lxd.daemon[1015]: => LXD is ready
Jan 26 21:35:33 plaes-blade lxd.daemon[1015]: t=2020-01-26T21:35:33+0200 lvl=eror msg="Error getting disk usage" err="Quotas disabled on filesystem" instance=massive-mastodon project=default
Jan 26 21:35:47 plaes-blade lxd.daemon[1015]: t=2020-01-26T21:35:47+0200 lvl=eror msg="Error getting disk usage" err="Quotas disabled on filesystem" instance=massive-mastodon project=default
Jan 26 21:35:55 plaes-blade lxd.daemon[1015]: t=2020-01-26T21:35:55+0200 lvl=warn msg="Error getting disk usage" err="Quotas disabled on filesystem" instance=v1 project=default
Jan 26 21:35:55 plaes-blade lxd.daemon[1015]: t=2020-01-26T21:35:55+0200 lvl=eror msg="Error getting disk usage" err="Quotas disabled on filesystem" instance=massive-mastodon project=default
Jan 26 21:48:15 plaes-blade lxd.daemon[1015]: t=2020-01-26T21:48:15+0200 lvl=eror msg="Error getting disk usage" err="Quotas disabled on filesystem" instance=massive-mastodon project=default
Jan 26 21:48:15 plaes-blade lxd.daemon[1015]: t=2020-01-26T21:48:15+0200 lvl=warn msg="Error getting disk usage" err="Quotas disabled on filesystem" instance=v1 project=default
Jan 27 03:05:15 plaes-blade systemd[1]: Stopping Service for snap application lxd.daemon...
Jan 27 03:05:15 plaes-blade lxd.daemon[4291]: => Stop reason is: snap refresh
Jan 27 03:05:15 plaes-blade lxd.daemon[4291]: => Stopping LXD
Jan 27 03:05:15 plaes-blade lxd.daemon[1015]: => LXD exited cleanly
Jan 27 03:05:16 plaes-blade systemd[1]: snap.lxd.daemon.service: Succeeded.
Jan 27 03:05:16 plaes-blade systemd[1]: Stopped Service for snap application lxd.daemon.
Jan 27 03:05:20 plaes-blade systemd[1]: Started Service for snap application lxd.daemon.
Jan 27 03:05:20 plaes-blade lxd.daemon[4474]: => Preparing the system (13140)
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Loading snap configuration
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Setting up mntns symlink (mnt:[4026532481])
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Setting up mount propagation on /var/snap/lxd/common/lxd/storage-pools
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Setting up mount propagation on /var/snap/lxd/common/lxd/devices
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Setting up kmod wrapper
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Preparing /boot
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Preparing a clean copy of /run
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Preparing a clean copy of /etc
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Setting up ceph configuration
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Setting up LVM configuration
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Rotating logs
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Escaping the systemd cgroups
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ====> Detected cgroup V1
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Escaping the systemd process resource limits
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Disabling shiftfs on this kernel (auto)
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: ==> Detected kernel with partial AppArmor support
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: => Re-using existing LXCFS
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: => Starting LXD
Jan 27 03:05:21 plaes-blade lxd.daemon[4474]: t=2020-01-27T03:05:21+0200 lvl=warn msg=" - Couldn't find the CGroup memory swap accounting, swap limits will be ignored"
Jan 27 03:05:23 plaes-blade lxd.daemon[4474]: => LXD is ready
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]: mount namespace: 7
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]: hierarchies:
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:   0: fd:   8: rdma
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:   1: fd:   9: freezer
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:   2: fd:  10: perf_event
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:   3: fd:  11: cpuset
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:   4: fd:  12: blkio
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:   5: fd:  13: pids
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:   6: fd:  14: devices
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:   7: fd:  15: memory
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:   8: fd:  16: cpu,cpuacct
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:   9: fd:  17: net_cls,net_prio
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:  10: fd:  18: name=systemd
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]:  11: fd:  19: unified
Jan 27 04:41:29 plaes-blade lxd.daemon[1015]: lxcfs.c: 152: do_reload: lxcfs: reloaded
Jan 27 11:50:54 plaes-blade lxd.daemon[4474]: t=2020-01-27T11:50:54+0200 lvl=warn msg="Could not get VM state from agent" err="mkdir /var/snap/lxd/common/lxd/virtual-machines/v1: file exists" instance=v1

stgraber · January 27, 2020, 10:04am

This is really odd and not something we’re seeing here on our test Debian 10 system…
Any chance you can reproduce this on a machine that I could access to poke around?

It looks like mount masking in the mount table, causing our mount reshuffling logic to assume it’s on a fresh system every time, duplicating the mount entries every time it’s run but I can’t easily see the source of the problem looking at the host mount table so will need to trace the startup script and sideload a debug version of the mount handling binary to see where things go wrong.

plaes · January 28, 2020, 7:57am

Issue has been solved by @stgraber

snap lxc integration was had issues with the btrfs mounts during update: