lxc move fail with websocket: bad handshake on cluster with network latency between nodes

Open kriszos opened this issue 3 years ago • 19 comments

 * Distribution: Ubuntu
 * Distribution version: 20.04.3
 * The output of "lxc info" or if that fails:
config:
  cluster.https_address: 10.0.1.30:8443
  core.https_address: 10.0.1.30:8443
  core.trust_password: true
api_extensions:
- storage_zfs_remove_snapshots
- container_host_shutdown_timeout
- container_stop_priority
- container_syscall_filtering
- auth_pki
- container_last_used_at
- etag
- patch
- usb_devices
- https_allowed_credentials
- image_compression_algorithm
- directory_manipulation
- container_cpu_time
- storage_zfs_use_refquota
- storage_lvm_mount_options
- network
- profile_usedby
- container_push
- container_exec_recording
- certificate_update
- container_exec_signal_handling
- gpu_devices
- container_image_properties
- migration_progress
- id_map
- network_firewall_filtering
- network_routes
- storage
- file_delete
- file_append
- network_dhcp_expiry
- storage_lvm_vg_rename
- storage_lvm_thinpool_rename
- network_vlan
- image_create_aliases
- container_stateless_copy
- container_only_migration
- storage_zfs_clone_copy
- unix_device_rename
- storage_lvm_use_thinpool
- storage_rsync_bwlimit
- network_vxlan_interface
- storage_btrfs_mount_options
- entity_description
- image_force_refresh
- storage_lvm_lv_resizing
- id_map_base
- file_symlinks
- container_push_target
- network_vlan_physical
- storage_images_delete
- container_edit_metadata
- container_snapshot_stateful_migration
- storage_driver_ceph
- storage_ceph_user_name
- resource_limits
- storage_volatile_initial_source
- storage_ceph_force_osd_reuse
- storage_block_filesystem_btrfs
- resources
- kernel_limits
- storage_api_volume_rename
- macaroon_authentication
- network_sriov
- console
- restrict_devlxd
- migration_pre_copy
- infiniband
- maas_network
- devlxd_events
- proxy
- network_dhcp_gateway
- file_get_symlink
- network_leases
- unix_device_hotplug
- storage_api_local_volume_handling
- operation_description
- clustering
- event_lifecycle
- storage_api_remote_volume_handling
- nvidia_runtime
- container_mount_propagation
- container_backup
- devlxd_images
- container_local_cross_pool_handling
- proxy_unix
- proxy_udp
- clustering_join
- proxy_tcp_udp_multi_port_handling
- network_state
- proxy_unix_dac_properties
- container_protection_delete
- unix_priv_drop
- pprof_http
- proxy_haproxy_protocol
- network_hwaddr
- proxy_nat
- network_nat_order
- container_full
- candid_authentication
- backup_compression
- candid_config
- nvidia_runtime_config
- storage_api_volume_snapshots
- storage_unmapped
- projects
- candid_config_key
- network_vxlan_ttl
- container_incremental_copy
- usb_optional_vendorid
- snapshot_scheduling
- snapshot_schedule_aliases
- container_copy_project
- clustering_server_address
- clustering_image_replication
- container_protection_shift
- snapshot_expiry
- container_backup_override_pool
- snapshot_expiry_creation
- network_leases_location
- resources_cpu_socket
- resources_gpu
- resources_numa
- kernel_features
- id_map_current
- event_location
- storage_api_remote_volume_snapshots
- network_nat_address
- container_nic_routes
- rbac
- cluster_internal_copy
- seccomp_notify
- lxc_features
- container_nic_ipvlan
- network_vlan_sriov
- storage_cephfs
- container_nic_ipfilter
- resources_v2
- container_exec_user_group_cwd
- container_syscall_intercept
- container_disk_shift
- storage_shifted
- resources_infiniband
- daemon_storage
- instances
- image_types
- resources_disk_sata
- clustering_roles
- images_expiry
- resources_network_firmware
- backup_compression_algorithm
- ceph_data_pool_name
- container_syscall_intercept_mount
- compression_squashfs
- container_raw_mount
- container_nic_routed
- container_syscall_intercept_mount_fuse
- container_disk_ceph
- virtual-machines
- image_profiles
- clustering_architecture
- resources_disk_id
- storage_lvm_stripes
- vm_boot_priority
- unix_hotplug_devices
- api_filtering
- instance_nic_network
- clustering_sizing
- firewall_driver
- projects_limits
- container_syscall_intercept_hugetlbfs
- limits_hugepages
- container_nic_routed_gateway
- projects_restrictions
- custom_volume_snapshot_expiry
- volume_snapshot_scheduling
- trust_ca_certificates
- snapshot_disk_usage
- clustering_edit_roles
- container_nic_routed_host_address
- container_nic_ipvlan_gateway
- resources_usb_pci
- resources_cpu_threads_numa
- resources_cpu_core_die
- api_os
- container_nic_routed_host_table
- container_nic_ipvlan_host_table
- container_nic_ipvlan_mode
- resources_system
- images_push_relay
- network_dns_search
- container_nic_routed_limits
- instance_nic_bridged_vlan
- network_state_bond_bridge
- usedby_consistency
- custom_block_volumes
- clustering_failure_domains
- resources_gpu_mdev
- console_vga_type
- projects_limits_disk
- network_type_macvlan
- network_type_sriov
- container_syscall_intercept_bpf_devices
- network_type_ovn
- projects_networks
- projects_networks_restricted_uplinks
- custom_volume_backup
- backup_override_name
- storage_rsync_compression
- network_type_physical
- network_ovn_external_subnets
- network_ovn_nat
- network_ovn_external_routes_remove
- tpm_device_type
- storage_zfs_clone_copy_rebase
- gpu_mdev
- resources_pci_iommu
- resources_network_usb
- resources_disk_address
- network_physical_ovn_ingress_mode
- network_ovn_dhcp
- network_physical_routes_anycast
- projects_limits_instances
- network_state_vlan
- instance_nic_bridged_port_isolation
- instance_bulk_state_change
- network_gvrp
- instance_pool_move
- gpu_sriov
- pci_device_type
- storage_volume_state
- network_acl
- migration_stateful
- disk_state_quota
- storage_ceph_features
- projects_compression
- projects_images_remote_cache_expiry
- certificate_project
- network_ovn_acl
- projects_images_auto_update
- projects_restricted_cluster_target
- images_default_architecture
- network_ovn_acl_defaults
- gpu_mig
- project_usage
- network_bridge_acl
- warnings
- projects_restricted_backups_and_snapshots
- clustering_join_token
- clustering_description
- server_trusted_proxy
- clustering_update_cert
- storage_api_project
- server_instance_driver_operational
- server_supported_storage_drivers
- event_lifecycle_requestor_address
- resources_gpu_usb
- clustering_evacuation
- network_ovn_nat_address
- network_bgp
- network_forward
- custom_volume_refresh
- network_counters_errors_dropped
- metrics
- image_source_project
- clustering_config
- network_peer
- linux_sysctl
- network_dns
- ovn_nic_acceleration
- certificate_self_renewal
- instance_project_move
- storage_volume_project_move
- cloud_init
- network_dns_nat
- database_leader
- instance_all_projects
- clustering_groups
- ceph_rbd_du
- instance_get_full
- qemu_metrics
- gpu_mig_uuid
- event_project
- clustering_evacuation_live
- instance_allow_inconsistent_copy
api_status: stable
api_version: "1.0"
auth: trusted
public: false
auth_methods:
- tls
environment:
  addresses:
  - 10.0.1.30:8443
  architectures:
  - x86_64
  - i686
  certificate: |
    -----BEGIN CERTIFICATE-----
    MIIB9zCCAX2gAwIBAgIQAKR8eYGnbF+EvD3i0Q2/czAKBggqhkjOPQQDAzAwMRww
    GgYDVQQKExNsaW51eGNvbnRhaW5lcnMub3JnMRAwDgYDVQQDDAdyb290QG4xMB4X
    DTIyMDIwMjE4NTEwNloXDTMyMDEzMTE4NTEwNlowMDEcMBoGA1UEChMTbGludXhj
    b250YWluZXJzLm9yZzEQMA4GA1UEAwwHcm9vdEBuMTB2MBAGByqGSM49AgEGBSuB
    BAAiA2IABJ92bn9+Zafi3DNlQ1C21Zew9oKMRCZTQUHA2G9U7ZTVqli76qOGUc4n
    fAcasrnXOGkPP4AmbQYeoZSewuRHi2Tv0sjQBnrKOr1gnNXvFBnKcFYptyRTIf3n
    Cj6d1YF57qNcMFowDgYDVR0PAQH/BAQDAgWgMBMGA1UdJQQMMAoGCCsGAQUFBwMB
    MAwGA1UdEwEB/wQCMAAwJQYDVR0RBB4wHIICbjGHBH8AAAGHEAAAAAAAAAAAAAAA
    AAAAAAEwCgYIKoZIzj0EAwMDaAAwZQIxAMFPCl+cVhLJ/wEt+t9VE3dbcIs/qtFV
    lO3y/FeYBqju1Z1pcW80K/4lL+NU+1ZdiAIwAc6pef1thBUpauxvLUfdikMQbIgX
    2B07zaER8uITxdN7iWtAz9mmtpqF4H1Yf9HX
    -----END CERTIFICATE-----
  certificate_fingerprint: c1b8cf714ff7381fafa0ebc36f7eeb544b5d2dc14e8cdf35c2cfd762d9ba7e5d
  driver: lxc
  driver_version: 4.0.11
  firewall: nftables
  kernel: Linux
  kernel_architecture: x86_64
  kernel_features:
    netnsid_getifaddrs: "true"
    seccomp_listener: "true"
    seccomp_listener_continue: "true"
    shiftfs: "false"
    uevent_injection: "true"
    unpriv_fscaps: "true"
  kernel_version: 5.4.0-97-generic
  lxc_features:
    cgroup2: "true"
    core_scheduling: "true"
    devpts_fd: "true"
    idmapped_mounts_v2: "true"
    mount_injection_file: "true"
    network_gateway_device_route: "true"
    network_ipvlan: "true"
    network_l2proxy: "true"
    network_phys_macvlan_mtu: "true"
    network_veth_router: "true"
    pidfd: "true"
    seccomp_allow_deny_syntax: "true"
    seccomp_notify: "true"
    seccomp_proxy_send_notify_fd: "true"
  os_name: Ubuntu
  os_version: "20.04"
  project: default
  server: lxd
  server_clustered: true
  server_name: n1
  server_pid: 17334
  server_version: "4.22"
  storage: zfs
  storage_version: 0.8.3-1ubuntu12.13
  storage_supported_drivers:
  - name: zfs
    version: 0.8.3-1ubuntu12.13
    remote: false
  - name: ceph
    version: 15.2.14
    remote: true
  - name: btrfs
    version: 5.4.1
    remote: false
  - name: cephfs
    version: 15.2.14
    remote: true
  - name: dir
    version: "1"
    remote: false
  - name: lvm
    version: 2.03.07(2) (2019-11-30) / 1.02.167 (2019-11-30) / 4.41.0
    remote: false

Issue description

When moving a container between cluster nodes that has network latency between them and database leader, command fail with “Error: Copy instance operation failed: Failed instance creation: Error transferring instance data: websocket: bad handshake”

Steps to reproduce:

create cluster
create container
simulate latency between nodes (f.e. "tc qdisc add dev enp5s0 root netem delay 40ms")
attempt to move a container

Information to attach

[ ] Container configuration

architecture: x86_64
config:
  image.architecture: amd64
  image.description: Alpine edge amd64 (20220201_13:00)
  image.os: Alpine
  image.release: edge
  image.serial: "20220201_13:00"
  image.type: squashfs
  image.variant: default
  volatile.base_image: 859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee
  volatile.eth0.hwaddr: 00:16:3e:2f:90:a7
  volatile.idmap.base: "0"
  volatile.idmap.current: '[{"Isuid":true,"Isgid":false,"Hostid":1000000,"Nsid":0,"Maprange":1000000000},{"Isuid":false,"Isgid":true,"Hostid":1000000,"Nsid":0,"Maprange":1000000000}]'
  volatile.idmap.next: '[{"Isuid":true,"Isgid":false,"Hostid":1000000,"Nsid":0,"Maprange":1000000000},{"Isuid":false,"Isgid":true,"Hostid":1000000,"Nsid":0,"Maprange":1000000000}]'
  volatile.last_state.idmap: '[{"Isuid":true,"Isgid":false,"Hostid":1000000,"Nsid":0,"Maprange":1000000000},{"Isuid":false,"Isgid":true,"Hostid":1000000,"Nsid":0,"Maprange":1000000000}]'
  volatile.last_state.power: STOPPED
  volatile.uuid: 3c09669f-77ac-4060-8231-4461906378a9
devices:
  eth0:
    name: eth0
    nictype: macvlan
    parent: enp5s0
    type: nic
  root:
    path: /
    pool: local
    type: disk
ephemeral: false
profiles:
- default
stateful: false
description: ""

[ ] Main daemon log

source leader (n1) 
t=2022-02-03T00:19:00+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443
t=2022-02-03T00:19:00+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443
t=2022-02-03T00:19:00+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443
t=2022-02-03T00:19:00+0100 lvl=dbug msg="Completed heartbeat round" duration=2.023247623s local=10.0.1.30:8443
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Handling API request" ip=@ method=GET protocol=unix url=/1.0 username=root
t=2022-02-03T00:19:02+0100 lvl=dbug msg="WriteJSON\n\t{\n\t\t\"type\": \"sync\",\n\t\t\"status\": \"Success\",\n\t\t\"status_code\": 200,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\": {\n\t\t\t\"config\": {\n\t\t\t\t\"cluster.https_address\": \"10.0.1.30:8443\",\n\t\t\t\t\"core.https_address\": \"10.0.1.30:8443\",\n\t\t\t\t\"core.trust_password\": true\n\t\t\t},\n\t\t\t\"api_extensions\": [\n\t\t\t\t\"storage_zfs_remove_snapshots\",\n\t\t\t\t\"container_host_shutdown_timeout\",\n\t\t\t\t\"container_stop_priority\",\n\t\t\t\t\"container_syscall_filtering\",\n\t\t\t\t\"auth_pki\",\n\t\t\t\t\"container_last_used_at\",\n\t\t\t\t\"etag\",\n\t\t\t\t\"patch\",\n\t\t\t\t\"usb_devices\",\n\t\t\t\t\"https_allowed_credentials\",\n\t\t\t\t\"image_compression_algorithm\",\n\t\t\t\t\"directory_manipulation\",\n\t\t\t\t\"container_cpu_time\",\n\t\t\t\t\"storage_zfs_use_refquota\",\n\t\t\t\t\"storage_lvm_mount_options\",\n\t\t\t\t\"network\",\n\t\t\t\t\"profile_usedby\",\n\t\t\t\t\"container_push\",\n\t\t\t\t\"container_exec_recording\",\n\t\t\t\t\"certificate_update\",\n\t\t\t\t\"container_exec_signal_handling\",\n\t\t\t\t\"gpu_devices\",\n\t\t\t\t\"container_image_properties\",\n\t\t\t\t\"migration_progress\",\n\t\t\t\t\"id_map\",\n\t\t\t\t\"network_firewall_filtering\",\n\t\t\t\t\"network_routes\",\n\t\t\t\t\"storage\",\n\t\t\t\t\"file_delete\",\n\t\t\t\t\"file_append\",\n\t\t\t\t\"network_dhcp_expiry\",\n\t\t\t\t\"storage_lvm_vg_rename\",\n\t\t\t\t\"storage_lvm_thinpool_rename\",\n\t\t\t\t\"network_vlan\",\n\t\t\t\t\"image_create_aliases\",\n\t\t\t\t\"container_stateless_copy\",\n\t\t\t\t\"container_only_migration\",\n\t\t\t\t\"storage_zfs_clone_copy\",\n\t\t\t\t\"unix_device_rename\",\n\t\t\t\t\"storage_lvm_use_thinpool\",\n\t\t\t\t\"storage_rsync_bwlimit\",\n\t\t\t\t\"network_vxlan_interface\",\n\t\t\t\t\"storage_btrfs_mount_options\",\n\t\t\t\t\"entity_description\",\n\t\t\t\t\"image_force_refresh\",\n\t\t\t\t\"storage_lvm_lv_resizing\",\n\t\t\t\t\"id_map_base\",\n\t\t\t\t\"file_symlinks\",\n\t\t\t\t\"container_push_target\",\n\t\t\t\t\"network_vlan_physical\",\n\t\t\t\t\"storage_images_delete\",\n\t\t\t\t\"container_edit_metadata\",\n\t\t\t\t\"container_snapshot_stateful_migration\",\n\t\t\t\t\"storage_driver_ceph\",\n\t\t\t\t\"storage_ceph_user_name\",\n\t\t\t\t\"resource_limits\",\n\t\t\t\t\"storage_volatile_initial_source\",\n\t\t\t\t\"storage_ceph_force_osd_reuse\",\n\t\t\t\t\"storage_block_filesystem_btrfs\",\n\t\t\t\t\"resources\",\n\t\t\t\t\"kernel_limits\",\n\t\t\t\t\"storage_api_volume_rename\",\n\t\t\t\t\"macaroon_authentication\",\n\t\t\t\t\"network_sriov\",\n\t\t\t\t\"console\",\n\t\t\t\t\"restrict_devlxd\",\n\t\t\t\t\"migration_pre_copy\",\n\t\t\t\t\"infiniband\",\n\t\t\t\t\"maas_network\",\n\t\t\t\t\"devlxd_events\",\n\t\t\t\t\"proxy\",\n\t\t\t\t\"network_dhcp_gateway\",\n\t\t\t\t\"file_get_symlink\",\n\t\t\t\t\"network_leases\",\n\t\t\t\t\"unix_device_hotplug\",\n\t\t\t\t\"storage_api_local_volume_handling\",\n\t\t\t\t\"operation_description\",\n\t\t\t\t\"clustering\",\n\t\t\t\t\"event_lifecycle\",\n\t\t\t\t\"storage_api_remote_volume_handling\",\n\t\t\t\t\"nvidia_runtime\",\n\t\t\t\t\"container_mount_propagation\",\n\t\t\t\t\"container_backup\",\n\t\t\t\t\"devlxd_images\",\n\t\t\t\t\"container_local_cross_pool_handling\",\n\t\t\t\t\"proxy_unix\",\n\t\t\t\t\"proxy_udp\",\n\t\t\t\t\"clustering_join\",\n\t\t\t\t\"proxy_tcp_udp_multi_port_handling\",\n\t\t\t\t\"network_state\",\n\t\t\t\t\"proxy_unix_dac_properties\",\n\t\t\t\t\"container_protection_delete\",\n\t\t\t\t\"unix_priv_drop\",\n\t\t\t\t\"pprof_http\",\n\t\t\t\t\"proxy_haproxy_protocol\",\n\t\t\t\t\"network_hwaddr\",\n\t\t\t\t\"proxy_nat\",\n\t\t\t\t\"network_nat_order\",\n\t\t\t\t\"container_full\",\n\t\t\t\t\"candid_authentication\",\n\t\t\t\t\"backup_compression\",\n\t\t\t\t\"candid_config\",\n\t\t\t\t\"nvidia_runtime_config\",\n\t\t\t\t\"storage_api_volume_snapshots\",\n\t\t\t\t\"storage_unmapped\",\n\t\t\t\t\"projects\",\n\t\t\t\t\"candid_config_key\",\n\t\t\t\t\"network_vxlan_ttl\",\n\t\t\t\t\"container_incremental_copy\",\n\t\t\t\t\"usb_optional_vendorid\",\n\t\t\t\t\"snapshot_scheduling\",\n\t\t\t\t\"snapshot_schedule_aliases\",\n\t\t\t\t\"container_copy_project\",\n\t\t\t\t\"clustering_server_address\",\n\t\t\t\t\"clustering_image_replication\",\n\t\t\t\t\"container_protection_shift\",\n\t\t\t\t\"snapshot_expiry\",\n\t\t\t\t\"container_backup_override_pool\",\n\t\t\t\t\"snapshot_expiry_creation\",\n\t\t\t\t\"network_leases_location\",\n\t\t\t\t\"resources_cpu_socket\",\n\t\t\t\t\"resources_gpu\",\n\t\t\t\t\"resources_numa\",\n\t\t\t\t\"kernel_features\",\n\t\t\t\t\"id_map_current\",\n\t\t\t\t\"event_location\",\n\t\t\t\t\"storage_api_remote_volume_snapshots\",\n\t\t\t\t\"network_nat_address\",\n\t\t\t\t\"container_nic_routes\",\n\t\t\t\t\"rbac\",\n\t\t\t\t\"cluster_internal_copy\",\n\t\t\t\t\"seccomp_notify\",\n\t\t\t\t\"lxc_features\",\n\t\t\t\t\"container_nic_ipvlan\",\n\t\t\t\t\"network_vlan_sriov\",\n\t\t\t\t\"storage_cephfs\",\n\t\t\t\t\"container_nic_ipfilter\",\n\t\t\t\t\"resources_v2\",\n\t\t\t\t\"container_exec_user_group_cwd\",\n\t\t\t\t\"container_syscall_intercept\",\n\t\t\t\t\"container_disk_shift\",\n\t\t\t\t\"storage_shifted\",\n\t\t\t\t\"resources_infiniband\",\n\t\t\t\t\"daemon_storage\",\n\t\t\t\t\"instances\",\n\t\t\t\t\"image_types\",\n\t\t\t\t\"resources_disk_sata\",\n\t\t\t\t\"clustering_roles\",\n\t\t\t\t\"images_expiry\",\n\t\t\t\t\"resources_network_firmware\",\n\t\t\t\t\"backup_compression_algorithm\",\n\t\t\t\t\"ceph_data_pool_name\",\n\t\t\t\t\"container_syscall_intercept_mount\",\n\t\t\t\t\"compression_squashfs\",\n\t\t\t\t\"container_raw_mount\",\n\t\t\t\t\"container_nic_routed\",\n\t\t\t\t\"container_syscall_intercept_mount_fuse\",\n\t\t\t\t\"container_disk_ceph\",\n\t\t\t\t\"virtual-machines\",\n\t\t\t\t\"image_profiles\",\n\t\t\t\t\"clustering_architecture\",\n\t\t\t\t\"resources_disk_id\",\n\t\t\t\t\"storage_lvm_stripes\",\n\t\t\t\t\"vm_boot_priority\",\n\t\t\t\t\"unix_hotplug_devices\",\n\t\t\t\t\"api_filtering\",\n\t\t\t\t\"instance_nic_network\",\n\t\t\t\t\"clustering_sizing\",\n\t\t\t\t\"firewall_driver\",\n\t\t\t\t\"projects_limits\",\n\t\t\t\t\"container_syscall_intercept_hugetlbfs\",\n\t\t\t\t\"limits_hugepages\",\n\t\t\t\t\"container_nic_routed_gateway\",\n\t\t\t\t\"projects_restrictions\",\n\t\t\t\t\"custom_volume_snapshot_expiry\",\n\t\t\t\t\"volume_snapshot_scheduling\",\n\t\t\t\t\"trust_ca_certificates\",\n\t\t\t\t\"snapshot_disk_usage\",\n\t\t\t\t\"clustering_edit_roles\",\n\t\t\t\t\"container_nic_routed_host_address\",\n\t\t\t\t\"container_nic_ipvlan_gateway\",\n\t\t\t\t\"resources_usb_pci\",\n\t\t\t\t\"resources_cpu_threads_numa\",\n\t\t\t\t\"resources_cpu_core_die\",\n\t\t\t\t\"api_os\",\n\t\t\t\t\"container_nic_routed_host_table\",\n\t\t\t\t\"container_nic_ipvlan_host_table\",\n\t\t\t\t\"container_nic_ipvlan_mode\",\n\t\t\t\t\"resources_system\",\n\t\t\t\t\"images_push_relay\",\n\t\t\t\t\"network_dns_search\",\n\t\t\t\t\"container_nic_routed_limits\",\n\t\t\t\t\"instance_nic_bridged_vlan\",\n\t\t\t\t\"network_state_bond_bridge\",\n\t\t\t\t\"usedby_consistency\",\n\t\t\t\t\"custom_block_volumes\",\n\t\t\t\t\"clustering_failure_domains\",\n\t\t\t\t\"resources_gpu_mdev\",\n\t\t\t\t\"console_vga_type\",\n\t\t\t\t\"projects_limits_disk\",\n\t\t\t\t\"network_type_macvlan\",\n\t\t\t\t\"network_type_sriov\",\n\t\t\t\t\"container_syscall_intercept_bpf_devices\",\n\t\t\t\t\"network_type_ovn\",\n\t\t\t\t\"projects_networks\",\n\t\t\t\t\"projects_networks_restricted_uplinks\",\n\t\t\t\t\"custom_volume_backup\",\n\t\t\t\t\"backup_override_name\",\n\t\t\t\t\"storage_rsync_compression\",\n\t\t\t\t\"network_type_physical\",\n\t\t\t\t\"network_ovn_external_subnets\",\n\t\t\t\t\"network_ovn_nat\",\n\t\t\t\t\"network_ovn_external_routes_remove\",\n\t\t\t\t\"tpm_device_type\",\n\t\t\t\t\"storage_zfs_clone_copy_rebase\",\n\t\t\t\t\"gpu_mdev\",\n\t\t\t\t\"resources_pci_iommu\",\n\t\t\t\t\"resources_network_usb\",\n\t\t\t\t\"resources_disk_address\",\n\t\t\t\t\"network_physical_ovn_ingress_mode\",\n\t\t\t\t\"network_ovn_dhcp\",\n\t\t\t\t\"network_physical_routes_anycast\",\n\t\t\t\t\"projects_limits_instances\",\n\t\t\t\t\"network_state_vlan\",\n\t\t\t\t\"instance_nic_bridged_port_isolation\",\n\t\t\t\t\"instance_bulk_state_change\",\n\t\t\t\t\"network_gvrp\",\n\t\t\t\t\"instance_pool_move\",\n\t\t\t\t\"gpu_sriov\",\n\t\t\t\t\"pci_device_type\",\n\t\t\t\t\"storage_volume_state\",\n\t\t\t\t\"network_acl\",\n\t\t\t\t\"migration_stateful\",\n\t\t\t\t\"disk_state_quota\",\n\t\t\t\t\"storage_ceph_features\",\n\t\t\t\t\"projects_compression\",\n\t\t\t\t\"projects_images_remote_cache_expiry\",\n\t\t\t\t\"certificate_project\",\n\t\t\t\t\"network_ovn_acl\",\n\t\t\t\t\"projects_images_auto_update\",\n\t\t\t\t\"projects_restricted_cluster_target\",\n\t\t\t\t\"images_default_architecture\",\n\t\t\t\t\"network_ovn_acl_defaults\",\n\t\t\t\t\"gpu_mig\",\n\t\t\t\t\"project_usage\",\n\t\t\t\t\"network_bridge_acl\",\n\t\t\t\t\"warnings\",\n\t\t\t\t\"projects_restricted_backups_and_snapshots\",\n\t\t\t\t\"clustering_join_token\",\n\t\t\t\t\"clustering_description\",\n\t\t\t\t\"server_trusted_proxy\",\n\t\t\t\t\"clustering_update_cert\",\n\t\t\t\t\"storage_api_project\",\n\t\t\t\t\"server_instance_driver_operational\",\n\t\t\t\t\"server_supported_storage_drivers\",\n\t\t\t\t\"event_lifecycle_requestor_address\",\n\t\t\t\t\"resources_gpu_usb\",\n\t\t\t\t\"clustering_evacuation\",\n\t\t\t\t\"network_ovn_nat_address\",\n\t\t\t\t\"network_bgp\",\n\t\t\t\t\"network_forward\",\n\t\t\t\t\"custom_volume_refresh\",\n\t\t\t\t\"network_counters_errors_dropped\",\n\t\t\t\t\"metrics\",\n\t\t\t\t\"image_source_project\",\n\t\t\t\t\"clustering_config\",\n\t\t\t\t\"network_peer\",\n\t\t\t\t\"linux_sysctl\",\n\t\t\t\t\"network_dns\",\n\t\t\t\t\"ovn_nic_acceleration\",\n\t\t\t\t\"certificate_self_renewal\",\n\t\t\t\t\"instance_project_move\",\n\t\t\t\t\"storage_volume_project_move\",\n\t\t\t\t\"cloud_init\",\n\t\t\t\t\"network_dns_nat\",\n\t\t\t\t\"database_leader\",\n\t\t\t\t\"instance_all_projects\",\n\t\t\t\t\"clustering_groups\",\n\t\t\t\t\"ceph_rbd_du\",\n\t\t\t\t\"instance_get_full\",\n\t\t\t\t\"qemu_metrics\",\n\t\t\t\t\"gpu_mig_uuid\",\n\t\t\t\t\"event_project\",\n\t\t\t\t\"clustering_evacuation_live\",\n\t\t\t\t\"instance_allow_inconsistent_copy\"\n\t\t\t],\n\t\t\t\"api_status\": \"stable\",\n\t\t\t\"api_version\": \"1.0\",\n\t\t\t\"auth\": \"trusted\",\n\t\t\t\"public\": false,\n\t\t\t\"auth_methods\": [\n\t\t\t\t\"tls\"\n\t\t\t],\n\t\t\t\"environment\": {\n\t\t\t\t\"addresses\": [\n\t\t\t\t\t\"10.0.1.30:8443\"\n\t\t\t\t],\n\t\t\t\t\"architectures\": [\n\t\t\t\t\t\"x86_64\",\n\t\t\t\t\t\"i686\"\n\t\t\t\t],\n\t\t\t\t\"certificate\": \"-----BEGIN CERTIFICATE-----\\nMIIB9zCCAX2gAwIBAgIQAKR8eYGnbF+EvD3i0Q2/czAKBggqhkjOPQQDAzAwMRww\\nGgYDVQQKExNsaW51eGNvbnRhaW5lcnMub3JnMRAwDgYDVQQDDAdyb290QG4xMB4X\\nDTIyMDIwMjE4NTEwNloXDTMyMDEzMTE4NTEwNlowMDEcMBoGA1UEChMTbGludXhj\\nb250YWluZXJzLm9yZzEQMA4GA1UEAwwHcm9vdEBuMTB2MBAGByqGSM49AgEGBSuB\\nBAAiA2IABJ92bn9+Zafi3DNlQ1C21Zew9oKMRCZTQUHA2G9U7ZTVqli76qOGUc4n\\nfAcasrnXOGkPP4AmbQYeoZSewuRHi2Tv0sjQBnrKOr1gnNXvFBnKcFYptyRTIf3n\\nCj6d1YF57qNcMFowDgYDVR0PAQH/BAQDAgWgMBMGA1UdJQQMMAoGCCsGAQUFBwMB\\nMAwGA1UdEwEB/wQCMAAwJQYDVR0RBB4wHIICbjGHBH8AAAGHEAAAAAAAAAAAAAAA\\nAAAAAAEwCgYIKoZIzj0EAwMDaAAwZQIxAMFPCl+cVhLJ/wEt+t9VE3dbcIs/qtFV\\nlO3y/FeYBqju1Z1pcW80K/4lL+NU+1ZdiAIwAc6pef1thBUpauxvLUfdikMQbIgX\\n2B07zaER8uITxdN7iWtAz9mmtpqF4H1Yf9HX\\n-----END CERTIFICATE-----\\n\",\n\t\t\t\t\"certificate_fingerprint\": \"c1b8cf714ff7381fafa0ebc36f7eeb544b5d2dc14e8cdf35c2cfd762d9ba7e5d\",\n\t\t\t\t\"driver\": \"lxc\",\n\t\t\t\t\"driver_version\": \"4.0.11\",\n\t\t\t\t\"firewall\": \"nftables\",\n\t\t\t\t\"kernel\": \"Linux\",\n\t\t\t\t\"kernel_architecture\": \"x86_64\",\n\t\t\t\t\"kernel_features\": {\n\t\t\t\t\t\"netnsid_getifaddrs\": \"true\",\n\t\t\t\t\t\"seccomp_listener\": \"true\",\n\t\t\t\t\t\"seccomp_listener_continue\": \"true\",\n\t\t\t\t\t\"shiftfs\": \"false\",\n\t\t\t\t\t\"uevent_injection\": \"true\",\n\t\t\t\t\t\"unpriv_fscaps\": \"true\"\n\t\t\t\t},\n\t\t\t\t\"kernel_version\": \"5.4.0-97-generic\",\n\t\t\t\t\"lxc_features\": {\n\t\t\t\t\t\"cgroup2\": \"true\",\n\t\t\t\t\t\"core_scheduling\": \"true\",\n\t\t\t\t\t\"devpts_fd\": \"true\",\n\t\t\t\t\t\"idmapped_mounts_v2\": \"true\",\n\t\t\t\t\t\"mount_injection_file\": \"true\",\n\t\t\t\t\t\"network_gateway_device_route\": \"true\",\n\t\t\t\t\t\"network_ipvlan\": \"true\",\n\t\t\t\t\t\"network_l2proxy\": \"true\",\n\t\t\t\t\t\"network_phys_macvlan_mtu\": \"true\",\n\t\t\t\t\t\"network_veth_router\": \"true\",\n\t\t\t\t\t\"pidfd\": \"true\",\n\t\t\t\t\t\"seccomp_allow_deny_syntax\": \"true\",\n\t\t\t\t\t\"seccomp_notify\": \"true\",\n\t\t\t\t\t\"seccomp_proxy_send_notify_fd\": \"true\"\n\t\t\t\t},\n\t\t\t\t\"os_name\": \"Ubuntu\",\n\t\t\t\t\"os_version\": \"20.04\",\n\t\t\t\t\"project\": \"default\",\n\t\t\t\t\"server\": \"lxd\",\n\t\t\t\t\"server_clustered\": true,\n\t\t\t\t\"server_name\": \"n1\",\n\t\t\t\t\"server_pid\": 17334,\n\t\t\t\t\"server_version\": \"4.22\",\n\t\t\t\t\"storage\": \"zfs\",\n\t\t\t\t\"storage_version\": \"0.8.3-1ubuntu12.13\",\n\t\t\t\t\"storage_supported_drivers\": [\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\": \"zfs\",\n\t\t\t\t\t\t\"Version\": \"0.8.3-1ubuntu12.13\",\n\t\t\t\t\t\t\"Remote\": false\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\": \"ceph\",\n\t\t\t\t\t\t\"Version\": \"15.2.14\",\n\t\t\t\t\t\t\"Remote\": true\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\": \"btrfs\",\n\t\t\t\t\t\t\"Version\": \"5.4.1\",\n\t\t\t\t\t\t\"Remote\": false\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\": \"cephfs\",\n\t\t\t\t\t\t\"Version\": \"15.2.14\",\n\t\t\t\t\t\t\"Remote\": true\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\": \"dir\",\n\t\t\t\t\t\t\"Version\": \"1\",\n\t\t\t\t\t\t\"Remote\": false\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\": \"lvm\",\n\t\t\t\t\t\t\"Version\": \"2.03.07(2) (2019-11-30) / 1.02.167 (2019-11-30) / 4.41.0\",\n\t\t\t\t\t\t\"Remote\": false\n\t\t\t\t\t}\n\t\t\t\t]\n\t\t\t}\n\t\t}\n\t}" http_code=200
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Handling API request" ip=@ method=GET protocol=unix url="/1.0/events?target=n2" username=root
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Event listener server handler started" listener=c6a309f8-0aec-42c1-be33-4bbbe8dc24be local=/var/snap/lxd/common/lxd/unix.socket localOnly=false remote=@
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Handling API request" ip=@ method=POST protocol=unix url="/1.0/instances/test1?target=n2" username=root
t=2022-02-03T00:19:02+0100 lvl=dbug msg="New task Operation: 259d3106-93fc-4db6-bd37-d351268bc49a" 
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Started task operation: 259d3106-93fc-4db6-bd37-d351268bc49a" 
t=2022-02-03T00:19:02+0100 lvl=dbug msg="WriteJSON\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/259d3106-93fc-4db6-bd37-d351268bc49a\",\n\t\t\"error_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\": {\n\t\t\t\"id\": \"259d3106-93fc-4db6-bd37-d351268bc49a\",\n\t\t\t\"class\": \"task\",\n\t\t\t\"description\": \"Migrating instance\",\n\t\t\t\"created_at\": \"2022-02-03T00:19:02.515856943+01:00\",\n\t\t\t\"updated_at\": \"2022-02-03T00:19:02.515856943+01: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/containers/test1\"\n\t\t\t\t],\n\t\t\t\t\"instances\": [\n\t\t\t\t\t\"/1.0/instances/test1\"\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\": \"n1\"\n\t\t}\n\t}" http_code=202
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Handling API request" ip=@ method=GET protocol=unix url="/1.0/operations/259d3106-93fc-4db6-bd37-d351268bc49a?target=n2" username=root
t=2022-02-03T00:19:02+0100 lvl=dbug msg="WriteJSON\n\t{\n\t\t\"type\": \"sync\",\n\t\t\"status\": \"Success\",\n\t\t\"status_code\": 200,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\": {\n\t\t\t\"id\": \"259d3106-93fc-4db6-bd37-d351268bc49a\",\n\t\t\t\"class\": \"task\",\n\t\t\t\"description\": \"Migrating instance\",\n\t\t\t\"created_at\": \"2022-02-03T00:19:02.515856943+01:00\",\n\t\t\t\"updated_at\": \"2022-02-03T00:19:02.515856943+01: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/containers/test1\"\n\t\t\t\t],\n\t\t\t\t\"instances\": [\n\t\t\t\t\t\"/1.0/instances/test1\"\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\": \"n1\"\n\t\t}\n\t}" http_code=200
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Connecting to a remote LXD over HTTPS" 
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Connecting to a remote LXD over HTTPS" 
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Sending request to LXD" etag= method=GET url="https://10.0.1.30:8443/1.0/instances/test1?project=default"
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:59110 method=GET protocol=cluster url="/1.0/instances/test1?project=default" username=
t=2022-02-03T00:19:02+0100 lvl=dbug msg="WriteJSON\n\t{\n\t\t\"type\": \"sync\",\n\t\t\"status\": \"Success\",\n\t\t\"status_code\": 200,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\": {\n\t\t\t\"architecture\": \"x86_64\",\n\t\t\t\"config\": {\n\t\t\t\t\"image.architecture\": \"amd64\",\n\t\t\t\t\"image.description\": \"Alpine edge amd64 (20220201_13:00)\",\n\t\t\t\t\"image.os\": \"Alpine\",\n\t\t\t\t\"image.release\": \"edge\",\n\t\t\t\t\"image.serial\": \"20220201_13:00\",\n\t\t\t\t\"image.type\": \"squashfs\",\n\t\t\t\t\"image.variant\": \"default\",\n\t\t\t\t\"volatile.base_image\": \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\t\"volatile.eth0.hwaddr\": \"00:16:3e:2f:90:a7\",\n\t\t\t\t\"volatile.idmap.base\": \"0\",\n\t\t\t\t\"volatile.idmap.current\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.idmap.next\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.last_state.idmap\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.last_state.power\": \"STOPPED\",\n\t\t\t\t\"volatile.uuid\": \"3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t},\n\t\t\t\"devices\": {},\n\t\t\t\"ephemeral\": false,\n\t\t\t\"profiles\": [\n\t\t\t\t\"default\"\n\t\t\t],\n\t\t\t\"stateful\": false,\n\t\t\t\"description\": \"\",\n\t\t\t\"created_at\": \"2022-02-02T22:43:16.026113691Z\",\n\t\t\t\"expanded_config\": {\n\t\t\t\t\"image.architecture\": \"amd64\",\n\t\t\t\t\"image.description\": \"Alpine edge amd64 (20220201_13:00)\",\n\t\t\t\t\"image.os\": \"Alpine\",\n\t\t\t\t\"image.release\": \"edge\",\n\t\t\t\t\"image.serial\": \"20220201_13:00\",\n\t\t\t\t\"image.type\": \"squashfs\",\n\t\t\t\t\"image.variant\": \"default\",\n\t\t\t\t\"volatile.base_image\": \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\t\"volatile.eth0.hwaddr\": \"00:16:3e:2f:90:a7\",\n\t\t\t\t\"volatile.idmap.base\": \"0\",\n\t\t\t\t\"volatile.idmap.current\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.idmap.next\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.last_state.idmap\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.last_state.power\": \"STOPPED\",\n\t\t\t\t\"volatile.uuid\": \"3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t},\n\t\t\t\"expanded_devices\": {\n\t\t\t\t\"eth0\": {\n\t\t\t\t\t\"name\": \"eth0\",\n\t\t\t\t\t\"nictype\": \"macvlan\",\n\t\t\t\t\t\"parent\": \"enp5s0\",\n\t\t\t\t\t\"type\": \"nic\"\n\t\t\t\t},\n\t\t\t\t\"root\": {\n\t\t\t\t\t\"path\": \"/\",\n\t\t\t\t\t\"pool\": \"local\",\n\t\t\t\t\t\"type\": \"disk\"\n\t\t\t\t}\n\t\t\t},\n\t\t\t\"name\": \"test1\",\n\t\t\t\"status\": \"Stopped\",\n\t\t\t\"status_code\": 102,\n\t\t\t\"last_used_at\": \"1970-01-01T00:00:00Z\",\n\t\t\t\"location\": \"n1\",\n\t\t\t\"type\": \"container\",\n\t\t\t\"project\": \"default\"\n\t\t}\n\t}" http_code=200
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Got response struct from LXD" 
t=2022-02-03T00:19:02+0100 lvl=dbug msg="\n\t{\n\t\t\"architecture\": \"x86_64\",\n\t\t\"config\": {\n\t\t\t\"image.architecture\": \"amd64\",\n\t\t\t\"image.description\": \"Alpine edge amd64 (20220201_13:00)\",\n\t\t\t\"image.os\": \"Alpine\",\n\t\t\t\"image.release\": \"edge\",\n\t\t\t\"image.serial\": \"20220201_13:00\",\n\t\t\t\"image.type\": \"squashfs\",\n\t\t\t\"image.variant\": \"default\",\n\t\t\t\"volatile.base_image\": \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\"volatile.eth0.hwaddr\": \"00:16:3e:2f:90:a7\",\n\t\t\t\"volatile.idmap.base\": \"0\",\n\t\t\t\"volatile.idmap.current\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.idmap.next\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.idmap\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.power\": \"STOPPED\",\n\t\t\t\"volatile.uuid\": \"3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t},\n\t\t\"devices\": {},\n\t\t\"ephemeral\": false,\n\t\t\"profiles\": [\n\t\t\t\"default\"\n\t\t],\n\t\t\"stateful\": false,\n\t\t\"description\": \"\",\n\t\t\"created_at\": \"2022-02-02T22:43:16.026113691Z\",\n\t\t\"expanded_config\": {\n\t\t\t\"image.architecture\": \"amd64\",\n\t\t\t\"image.description\": \"Alpine edge amd64 (20220201_13:00)\",\n\t\t\t\"image.os\": \"Alpine\",\n\t\t\t\"image.release\": \"edge\",\n\t\t\t\"image.serial\": \"20220201_13:00\",\n\t\t\t\"image.type\": \"squashfs\",\n\t\t\t\"image.variant\": \"default\",\n\t\t\t\"volatile.base_image\": \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\"volatile.eth0.hwaddr\": \"00:16:3e:2f:90:a7\",\n\t\t\t\"volatile.idmap.base\": \"0\",\n\t\t\t\"volatile.idmap.current\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.idmap.next\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.idmap\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.power\": \"STOPPED\",\n\t\t\t\"volatile.uuid\": \"3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t},\n\t\t\"expanded_devices\": {\n\t\t\t\"eth0\": {\n\t\t\t\t\"name\": \"eth0\",\n\t\t\t\t\"nictype\": \"macvlan\",\n\t\t\t\t\"parent\": \"enp5s0\",\n\t\t\t\t\"type\": \"nic\"\n\t\t\t},\n\t\t\t\"root\": {\n\t\t\t\t\"path\": \"/\",\n\t\t\t\t\"pool\": \"local\",\n\t\t\t\t\"type\": \"disk\"\n\t\t\t}\n\t\t},\n\t\t\"name\": \"test1\",\n\t\t\"status\": \"Stopped\",\n\t\t\"status_code\": 102,\n\t\t\"last_used_at\": \"1970-01-01T00:00:00Z\",\n\t\t\"location\": \"n1\",\n\t\t\"type\": \"container\",\n\t\t\"project\": \"default\"\n\t}" 
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:59112 method=GET protocol=cluster url="/1.0/events?project=default" username=
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Connected to the websocket: wss://10.0.1.30:8443/1.0/events?project=default" 
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Sending request to LXD" etag= method=POST url="https://10.0.1.30:8443/1.0/instances/test1?project=default"
t=2022-02-03T00:19:02+0100 lvl=dbug msg="\n\t{\n\t\t\"name\": \"\",\n\t\t\"migration\": true,\n\t\t\"live\": false,\n\t\t\"instance_only\": false,\n\t\t\"container_only\": false,\n\t\t\"target\": null,\n\t\t\"pool\": \"\",\n\t\t\"project\": \"\"\n\t}" 
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Event listener server handler started" listener=007171fc-824a-469a-aa93-57a320c08b4f local=10.0.1.30:8443 localOnly=true remote=10.0.1.30:59112
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:59114 method=POST protocol=cluster url="/1.0/instances/test1?project=default" username=
t=2022-02-03T00:19:02+0100 lvl=dbug msg="New websocket Operation: cd1b2ae1-b4c5-4e19-a06c-74ddc95c716d" 
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Started websocket operation: cd1b2ae1-b4c5-4e19-a06c-74ddc95c716d" 
t=2022-02-03T00:19:02+0100 lvl=info msg="Waiting for migration channel connections" 
t=2022-02-03T00:19:02+0100 lvl=dbug msg="WriteJSON\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/cd1b2ae1-b4c5-4e19-a06c-74ddc95c716d\",\n\t\t\"error_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\": {\n\t\t\t\"id\": \"cd1b2ae1-b4c5-4e19-a06c-74ddc95c716d\",\n\t\t\t\"class\": \"websocket\",\n\t\t\t\"description\": \"Migrating instance\",\n\t\t\t\"created_at\": \"2022-02-03T00:19:02.644793462+01:00\",\n\t\t\t\"updated_at\": \"2022-02-03T00:19:02.644793462+01: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/containers/test1\"\n\t\t\t\t],\n\t\t\t\t\"instances\": [\n\t\t\t\t\t\"/1.0/instances/test1\"\n\t\t\t\t]\n\t\t\t},\n\t\t\t\"metadata\": {\n\t\t\t\t\"control\": \"6e3719dd8b7453ece588f13d39cd9241e98a9021a62c05f5606ca1380bc419a1\",\n\t\t\t\t\"fs\": \"f1e0512d5259cabe5b52ac61cb23fe004e2a47f22cf1e79c0ed8a42fb3bd6472\"\n\t\t\t},\n\t\t\t\"may_cancel\": true,\n\t\t\t\"err\": \"\",\n\t\t\t\"location\": \"n1\"\n\t\t}\n\t}" http_code=202
t=2022-02-03T00:19:02+0100 lvl=dbug msg="Got operation from LXD" 
t=2022-02-03T00:19:02+0100 lvl=dbug msg="\n\t{\n\t\t\"id\": \"cd1b2ae1-b4c5-4e19-a06c-74ddc95c716d\",\n\t\t\"class\": \"websocket\",\n\t\t\"description\": \"Migrating instance\",\n\t\t\"created_at\": \"2022-02-03T00:19:02.644793462+01:00\",\n\t\t\"updated_at\": \"2022-02-03T00:19:02.644793462+01:00\",\n\t\t\"status\": \"Running\",\n\t\t\"status_code\": 103,\n\t\t\"resources\": {\n\t\t\t\"containers\": [\n\t\t\t\t\"/1.0/containers/test1\"\n\t\t\t],\n\t\t\t\"instances\": [\n\t\t\t\t\"/1.0/instances/test1\"\n\t\t\t]\n\t\t},\n\t\t\"metadata\": {\n\t\t\t\"control\": \"6e3719dd8b7453ece588f13d39cd9241e98a9021a62c05f5606ca1380bc419a1\",\n\t\t\t\"fs\": \"f1e0512d5259cabe5b52ac61cb23fe004e2a47f22cf1e79c0ed8a42fb3bd6472\"\n\t\t},\n\t\t\"may_cancel\": true,\n\t\t\"err\": \"\",\n\t\t\"location\": \"n1\"\n\t}" 
t=2022-02-03T00:19:03+0100 lvl=dbug msg="Connected to the websocket: wss://10.0.1.31:8443/1.0/events?project=default&target=n2" 
t=2022-02-03T00:19:03+0100 lvl=dbug msg="Sending request to LXD" etag= method=POST url="https://10.0.1.31:8443/1.0/instances?project=default&target=n2"
t=2022-02-03T00:19:03+0100 lvl=dbug msg="\n\t{\n\t\t\"architecture\": \"x86_64\",\n\t\t\"config\": {\n\t\t\t\"image.architecture\": \"amd64\",\n\t\t\t\"image.description\": \"Alpine edge amd64 (20220201_13:00)\",\n\t\t\t\"image.os\": \"Alpine\",\n\t\t\t\"image.release\": \"edge\",\n\t\t\t\"image.serial\": \"20220201_13:00\",\n\t\t\t\"image.type\": \"squashfs\",\n\t\t\t\"image.variant\": \"default\",\n\t\t\t\"volatile.base_image\": \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\"volatile.eth0.hwaddr\": \"00:16:3e:2f:90:a7\",\n\t\t\t\"volatile.idmap.base\": \"0\",\n\t\t\t\"volatile.idmap.current\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.idmap.next\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.idmap\": \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.power\": \"STOPPED\",\n\t\t\t\"volatile.uuid\": \"3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t},\n\t\t\"devices\": {},\n\t\t\"ephemeral\": false,\n\t\t\"profiles\": [\n\t\t\t\"default\"\n\t\t],\n\t\t\"stateful\": false,\n\t\t\"description\": \"\",\n\t\t\"name\": \"lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\",\n\t\t\"source\": {\n\t\t\t\"type\": \"migration\",\n\t\t\t\"certificate\": \"-----BEGIN CERTIFICATE-----\\nMIIB9zCCAX2gAwIBAgIQAKR8eYGnbF+EvD3i0Q2/czAKBggqhkjOPQQDAzAwMRww\\nGgYDVQQKExNsaW51eGNvbnRhaW5lcnMub3JnMRAwDgYDVQQDDAdyb290QG4xMB4X\\nDTIyMDIwMjE4NTEwNloXDTMyMDEzMTE4NTEwNlowMDEcMBoGA1UEChMTbGludXhj\\nb250YWluZXJzLm9yZzEQMA4GA1UEAwwHcm9vdEBuMTB2MBAGByqGSM49AgEGBSuB\\nBAAiA2IABJ92bn9+Zafi3DNlQ1C21Zew9oKMRCZTQUHA2G9U7ZTVqli76qOGUc4n\\nfAcasrnXOGkPP4AmbQYeoZSewuRHi2Tv0sjQBnrKOr1gnNXvFBnKcFYptyRTIf3n\\nCj6d1YF57qNcMFowDgYDVR0PAQH/BAQDAgWgMBMGA1UdJQQMMAoGCCsGAQUFBwMB\\nMAwGA1UdEwEB/wQCMAAwJQYDVR0RBB4wHIICbjGHBH8AAAGHEAAAAAAAAAAAAAAA\\nAAAAAAEwCgYIKoZIzj0EAwMDaAAwZQIxAMFPCl+cVhLJ/wEt+t9VE3dbcIs/qtFV\\nlO3y/FeYBqju1Z1pcW80K/4lL+NU+1ZdiAIwAc6pef1thBUpauxvLUfdikMQbIgX\\n2B07zaER8uITxdN7iWtAz9mmtpqF4H1Yf9HX\\n-----END CERTIFICATE-----\\n\",\n\t\t\t\"base-image\": \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\"mode\": \"pull\",\n\t\t\t\"operation\": \"https://10.0.1.30:8443/1.0/operations/cd1b2ae1-b4c5-4e19-a06c-74ddc95c716d\",\n\t\t\t\"secrets\": {\n\t\t\t\t\"control\": \"6e3719dd8b7453ece588f13d39cd9241e98a9021a62c05f5606ca1380bc419a1\",\n\t\t\t\t\"fs\": \"f1e0512d5259cabe5b52ac61cb23fe004e2a47f22cf1e79c0ed8a42fb3bd6472\"\n\t\t\t},\n\t\t\t\"allow_inconsistent\": false\n\t\t},\n\t\t\"instance_type\": \"\",\n\t\t\"type\": \"container\"\n\t}" 
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Starting heartbeat round" local=10.0.1.30:8443 mode=normal
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Heartbeat updating local raft members" members="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:stand-by} Name:n2}]"
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Database error: Failed updating heartbeat time for member \"10.0.1.30:8443\": database is locked" 
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Retry failed db interaction (Failed updating heartbeat time for member \"10.0.1.30:8443\": database is locked)" 
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Database error: Failed updating heartbeat time for member \"10.0.1.30:8443\": database is locked" 
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Retry failed db interaction (Failed updating heartbeat time for member \"10.0.1.30:8443\": database is locked)" 
t=2022-02-03T00:19:09+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443
t=2022-02-03T00:19:09+0100 lvl=dbug msg="Completed heartbeat round" duration=854.16949ms local=10.0.1.30:8443
t=2022-02-03T00:19:12+0100 lvl=dbug msg="Failure for websocket operation: cd1b2ae1-b4c5-4e19-a06c-74ddc95c716d: Timed out waiting for connections" 
t=2022-02-03T00:19:14+0100 lvl=dbug msg="Allowing untrusted GET" ip=10.0.1.31:54506 url="/1.0/operations/cd1b2ae1-b4c5-4e19-a06c-74ddc95c716d/websocket?secret=6e3719dd8b7453ece588f13d39cd9241e98a9021a62c05f5606ca1380bc419a1"
t=2022-02-03T00:19:14+0100 lvl=dbug msg="Error Response\n\t{\n\t\t\"type\": \"error\",\n\t\t\"status\": \"\",\n\t\t\"status_code\": 0,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 500,\n\t\t\"error\": \"Only running operations can be connected\",\n\t\t\"metadata\": null\n\t}" http_code=500
t=2022-02-03T00:19:14+0100 lvl=dbug msg="Got operation from LXD" 
t=2022-02-03T00:19:14+0100 lvl=dbug msg="\n\t{\n\t\t\"id\": \"c8db2248-29e3-4fc5-8270-ac1f36df029f\",\n\t\t\"class\": \"task\",\n\t\t\"description\": \"Creating instance\",\n\t\t\"created_at\": \"2022-02-03T00:19:14.116012095+01:00\",\n\t\t\"updated_at\": \"2022-02-03T00:19:14.116012095+01:00\",\n\t\t\"status\": \"Running\",\n\t\t\"status_code\": 103,\n\t\t\"resources\": {\n\t\t\t\"containers\": [\n\t\t\t\t\"/1.0/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t],\n\t\t\t\"instances\": [\n\t\t\t\t\"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t]\n\t\t},\n\t\t\"metadata\": null,\n\t\t\"may_cancel\": false,\n\t\t\"err\": \"\",\n\t\t\"location\": \"n2\"\n\t}" 
t=2022-02-03T00:19:14+0100 lvl=dbug msg="Sending request to LXD" etag= method=GET url="https://10.0.1.31:8443/1.0/operations/c8db2248-29e3-4fc5-8270-ac1f36df029f?project=default&target=n2"
t=2022-02-03T00:19:15+0100 lvl=dbug msg="Got response struct from LXD" 
t=2022-02-03T00:19:15+0100 lvl=dbug msg="\n\t{\n\t\t\"id\": \"c8db2248-29e3-4fc5-8270-ac1f36df029f\",\n\t\t\"class\": \"task\",\n\t\t\"description\": \"Creating instance\",\n\t\t\"created_at\": \"2022-02-03T00:19:14.116012095+01:00\",\n\t\t\"updated_at\": \"2022-02-03T00:19:14.116012095+01:00\",\n\t\t\"status\": \"Running\",\n\t\t\"status_code\": 103,\n\t\t\"resources\": {\n\t\t\t\"containers\": [\n\t\t\t\t\"/1.0/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t],\n\t\t\t\"instances\": [\n\t\t\t\t\"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t]\n\t\t},\n\t\t\"metadata\": null,\n\t\t\"may_cancel\": false,\n\t\t\"err\": \"\",\n\t\t\"location\": \"n2\"\n\t}" 
t=2022-02-03T00:19:16+0100 lvl=dbug msg="Updated metadata for task Operation: 259d3106-93fc-4db6-bd37-d351268bc49a" 
t=2022-02-03T00:19:16+0100 lvl=dbug msg="Sending request to LXD" etag= method=DELETE url="https://10.0.1.30:8443/1.0/operations/cd1b2ae1-b4c5-4e19-a06c-74ddc95c716d?project=default"
t=2022-02-03T00:19:16+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:16+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:59128 method=DELETE protocol=cluster url="/1.0/operations/cd1b2ae1-b4c5-4e19-a06c-74ddc95c716d?project=default" username=
t=2022-02-03T00:19:16+0100 lvl=dbug msg="Error Response\n\t{\n\t\t\"type\": \"error\",\n\t\t\"status\": \"\",\n\t\t\"status_code\": 0,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 400,\n\t\t\"error\": \"Only running operations can be cancelled\",\n\t\t\"metadata\": null\n\t}" http_code=400
t=2022-02-03T00:19:16+0100 lvl=dbug msg="Failure for task operation: 259d3106-93fc-4db6-bd37-d351268bc49a: Copy instance operation failed: Failed instance creation: Error transferring instance data: websocket: bad handshake" 
t=2022-02-03T00:19:16+0100 lvl=dbug msg="Event listener server handler stopped" listener=c6a309f8-0aec-42c1-be33-4bbbe8dc24be local=/var/snap/lxd/common/lxd/unix.socket localOnly=false remote=@
t=2022-02-03T00:19:18+0100 lvl=dbug msg="Starting heartbeat round" local=10.0.1.30:8443 mode=normal
t=2022-02-03T00:19:18+0100 lvl=dbug msg="Heartbeat updating local raft members" members="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:stand-by} Name:n2}]"
t=2022-02-03T00:19:24+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443
t=2022-02-03T00:19:25+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443
t=2022-02-03T00:19:25+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443
t=2022-02-03T00:19:25+0100 lvl=dbug msg="Completed heartbeat round" duration=6.88398691s local=10.0.1.30:8443
t=2022-02-03T00:19:28+0100 lvl=dbug msg="Starting heartbeat round" local=10.0.1.30:8443 mode=normal
t=2022-02-03T00:19:28+0100 lvl=dbug msg="Heartbeat updating local raft members" members="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:stand-by} Name:n2}]"
t=2022-02-03T00:19:30+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443
t=2022-02-03T00:19:30+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443
t=2022-02-03T00:19:30+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443
t=2022-02-03T00:19:30+0100 lvl=dbug msg="Completed heartbeat round" duration=2.479718414s local=10.0.1.30:8443

destination (n2)

t=2022-02-03T00:19:00+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:00+0100 lvl=dbug msg="Replace current raft nodes" raftMembers="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:stand-by} Name:n2}]"
t=2022-02-03T00:19:03+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:03+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:34368 method=GET protocol=cluster url="/1.0/events?project=default&target=n2" username=
t=2022-02-03T00:19:03+0100 lvl=dbug msg="Event listener server handler started" listener=d84b70ef-55b5-4191-a5ee-42f324272d5e local=10.0.1.31:8443 localOnly=false remote=10.0.1.30:34368
t=2022-02-03T00:19:03+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:03+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:34370 method=POST protocol=cluster url="/1.0/instances?project=default&target=n2" username=
t=2022-02-03T00:19:03+0100 lvl=dbug msg="Responding to instance create" 
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Replace current raft nodes" raftMembers="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:stand-by} Name:n2}]"
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Instance operation lock created" action=create instance=lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9 project=default reusable=false
t=2022-02-03T00:19:09+0100 lvl=info msg="Creating container" ephemeral=false instance=lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9 instanceType=container project=default
t=2022-02-03T00:19:11+0100 lvl=dbug msg="FillInstanceConfig started" driver=zfs instance=lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9 pool=local project=default
t=2022-02-03T00:19:11+0100 lvl=dbug msg="FillInstanceConfig finished" driver=zfs instance=lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9 pool=local project=default
t=2022-02-03T00:19:14+0100 lvl=info msg="Created container" ephemeral=false instance=lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9 instanceType=container project=default
t=2022-02-03T00:19:14+0100 lvl=dbug msg="New task Operation: c8db2248-29e3-4fc5-8270-ac1f36df029f" 
t=2022-02-03T00:19:14+0100 lvl=dbug msg="Instance operation lock finished" action=create err=nil instance=lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9 project=default reusable=false
t=2022-02-03T00:19:14+0100 lvl=dbug msg="Started task operation: c8db2248-29e3-4fc5-8270-ac1f36df029f" 
t=2022-02-03T00:19:14+0100 lvl=dbug msg="WriteJSON\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/c8db2248-29e3-4fc5-8270-ac1f36df029f\",\n\t\t\"error_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\": {\n\t\t\t\"id\": \"c8db2248-29e3-4fc5-8270-ac1f36df029f\",\n\t\t\t\"class\": \"task\",\n\t\t\t\"description\": \"Creating instance\",\n\t\t\t\"created_at\": \"2022-02-03T00:19:14.116012095+01:00\",\n\t\t\t\"updated_at\": \"2022-02-03T00:19:14.116012095+01: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/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t\t],\n\t\t\t\t\"instances\": [\n\t\t\t\t\t\"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\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\": \"n2\"\n\t\t}\n\t}" http_code=202
t=2022-02-03T00:19:15+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:15+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:34378 method=GET protocol=cluster url="/1.0/operations/c8db2248-29e3-4fc5-8270-ac1f36df029f?project=default&target=n2" username=
t=2022-02-03T00:19:15+0100 lvl=dbug msg="WriteJSON\n\t{\n\t\t\"type\": \"sync\",\n\t\t\"status\": \"Success\",\n\t\t\"status_code\": 200,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\": {\n\t\t\t\"id\": \"c8db2248-29e3-4fc5-8270-ac1f36df029f\",\n\t\t\t\"class\": \"task\",\n\t\t\t\"description\": \"Creating instance\",\n\t\t\t\"created_at\": \"2022-02-03T00:19:14.116012095+01:00\",\n\t\t\t\"updated_at\": \"2022-02-03T00:19:14.116012095+01: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/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t\t],\n\t\t\t\t\"instances\": [\n\t\t\t\t\t\"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\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\": \"n2\"\n\t\t}\n\t}" http_code=200
t=2022-02-03T00:19:16+0100 lvl=dbug msg="Failure for task operation: c8db2248-29e3-4fc5-8270-ac1f36df029f: Error transferring instance data: websocket: bad handshake" 
t=2022-02-03T00:19:25+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:25+0100 lvl=dbug msg="Replace current raft nodes" raftMembers="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:stand-by} Name:n2}]"
t=2022-02-03T00:19:30+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:30+0100 lvl=dbug msg="Replace current raft nodes" raftMembers="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:stand-by} Name:n2}]"
t=2022-02-03T00:19:45+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:45+0100 lvl=dbug msg="Replace current raft nodes" raftMembers="[{NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:stand-by} Name:n2} {NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1}]"
t=2022-02-03T00:19:55+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org"
t=2022-02-03T00:19:55+0100 lvl=dbug msg="Replace current raft nodes" raftMembers="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:stand-by} Name:n2}]"

[ ] output of lxc monitor while reproducing the issue:

 location: n1
metadata:
  context:
    listener: 877980ae-3b24-422a-bfe7-4a1981950701
    local: /var/snap/lxd/common/lxd/unix.socket
    localOnly: "false"
    remote: '@'
  level: dbug
  message: Event listener server handler started
timestamp: "2022-02-03T01:49:58.976404827+01:00"
type: logging


location: n1
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0
    username: root
  level: dbug
  message: Handling API request
timestamp: "2022-02-03T01:50:01.309782636+01:00"
type: logging


location: n1
metadata:
  context:
    ip: '@'
    method: POST
    protocol: unix
    url: /1.0/instances/test1?target=n2
    username: root
  level: dbug
  message: Handling API request
timestamp: "2022-02-03T01:50:01.321456859+01:00"
type: logging


location: n1
metadata:
  context:
    http_code: "200"
  level: dbug
  message: "WriteJSON\n\t{\n\t\t\"type\": \"sync\",\n\t\t\"status\": \"Success\",\n\t\t\"status_code\":
    200,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\":
    {\n\t\t\t\"config\": {\n\t\t\t\t\"cluster.https_address\": \"10.0.1.30:8443\",\n\t\t\t\t\"core.https_address\":
    \"10.0.1.30:8443\",\n\t\t\t\t\"core.trust_password\": true\n\t\t\t},\n\t\t\t\"api_extensions\":
    [\n\t\t\t\t\"storage_zfs_remove_snapshots\",\n\t\t\t\t\"container_host_shutdown_timeout\",\n\t\t\t\t\"container_stop_priority\",\n\t\t\t\t\"container_syscall_filtering\",\n\t\t\t\t\"auth_pki\",\n\t\t\t\t\"container_last_used_at\",\n\t\t\t\t\"etag\",\n\t\t\t\t\"patch\",\n\t\t\t\t\"usb_devices\",\n\t\t\t\t\"https_allowed_credentials\",\n\t\t\t\t\"image_compression_algorithm\",\n\t\t\t\t\"directory_manipulation\",\n\t\t\t\t\"container_cpu_time\",\n\t\t\t\t\"storage_zfs_use_refquota\",\n\t\t\t\t\"storage_lvm_mount_options\",\n\t\t\t\t\"network\",\n\t\t\t\t\"profile_usedby\",\n\t\t\t\t\"container_push\",\n\t\t\t\t\"container_exec_recording\",\n\t\t\t\t\"certificate_update\",\n\t\t\t\t\"container_exec_signal_handling\",\n\t\t\t\t\"gpu_devices\",\n\t\t\t\t\"container_image_properties\",\n\t\t\t\t\"migration_progress\",\n\t\t\t\t\"id_map\",\n\t\t\t\t\"network_firewall_filtering\",\n\t\t\t\t\"network_routes\",\n\t\t\t\t\"storage\",\n\t\t\t\t\"file_delete\",\n\t\t\t\t\"file_append\",\n\t\t\t\t\"network_dhcp_expiry\",\n\t\t\t\t\"storage_lvm_vg_rename\",\n\t\t\t\t\"storage_lvm_thinpool_rename\",\n\t\t\t\t\"network_vlan\",\n\t\t\t\t\"image_create_aliases\",\n\t\t\t\t\"container_stateless_copy\",\n\t\t\t\t\"container_only_migration\",\n\t\t\t\t\"storage_zfs_clone_copy\",\n\t\t\t\t\"unix_device_rename\",\n\t\t\t\t\"storage_lvm_use_thinpool\",\n\t\t\t\t\"storage_rsync_bwlimit\",\n\t\t\t\t\"network_vxlan_interface\",\n\t\t\t\t\"storage_btrfs_mount_options\",\n\t\t\t\t\"entity_description\",\n\t\t\t\t\"image_force_refresh\",\n\t\t\t\t\"storage_lvm_lv_resizing\",\n\t\t\t\t\"id_map_base\",\n\t\t\t\t\"file_symlinks\",\n\t\t\t\t\"container_push_target\",\n\t\t\t\t\"network_vlan_physical\",\n\t\t\t\t\"storage_images_delete\",\n\t\t\t\t\"container_edit_metadata\",\n\t\t\t\t\"container_snapshot_stateful_migration\",\n\t\t\t\t\"storage_driver_ceph\",\n\t\t\t\t\"storage_ceph_user_name\",\n\t\t\t\t\"resource_limits\",\n\t\t\t\t\"storage_volatile_initial_source\",\n\t\t\t\t\"storage_ceph_force_osd_reuse\",\n\t\t\t\t\"storage_block_filesystem_btrfs\",\n\t\t\t\t\"resources\",\n\t\t\t\t\"kernel_limits\",\n\t\t\t\t\"storage_api_volume_rename\",\n\t\t\t\t\"macaroon_authentication\",\n\t\t\t\t\"network_sriov\",\n\t\t\t\t\"console\",\n\t\t\t\t\"restrict_devlxd\",\n\t\t\t\t\"migration_pre_copy\",\n\t\t\t\t\"infiniband\",\n\t\t\t\t\"maas_network\",\n\t\t\t\t\"devlxd_events\",\n\t\t\t\t\"proxy\",\n\t\t\t\t\"network_dhcp_gateway\",\n\t\t\t\t\"file_get_symlink\",\n\t\t\t\t\"network_leases\",\n\t\t\t\t\"unix_device_hotplug\",\n\t\t\t\t\"storage_api_local_volume_handling\",\n\t\t\t\t\"operation_description\",\n\t\t\t\t\"clustering\",\n\t\t\t\t\"event_lifecycle\",\n\t\t\t\t\"storage_api_remote_volume_handling\",\n\t\t\t\t\"nvidia_runtime\",\n\t\t\t\t\"container_mount_propagation\",\n\t\t\t\t\"container_backup\",\n\t\t\t\t\"devlxd_images\",\n\t\t\t\t\"container_local_cross_pool_handling\",\n\t\t\t\t\"proxy_unix\",\n\t\t\t\t\"proxy_udp\",\n\t\t\t\t\"clustering_join\",\n\t\t\t\t\"proxy_tcp_udp_multi_port_handling\",\n\t\t\t\t\"network_state\",\n\t\t\t\t\"proxy_unix_dac_properties\",\n\t\t\t\t\"container_protection_delete\",\n\t\t\t\t\"unix_priv_drop\",\n\t\t\t\t\"pprof_http\",\n\t\t\t\t\"proxy_haproxy_protocol\",\n\t\t\t\t\"network_hwaddr\",\n\t\t\t\t\"proxy_nat\",\n\t\t\t\t\"network_nat_order\",\n\t\t\t\t\"container_full\",\n\t\t\t\t\"candid_authentication\",\n\t\t\t\t\"backup_compression\",\n\t\t\t\t\"candid_config\",\n\t\t\t\t\"nvidia_runtime_config\",\n\t\t\t\t\"storage_api_volume_snapshots\",\n\t\t\t\t\"storage_unmapped\",\n\t\t\t\t\"projects\",\n\t\t\t\t\"candid_config_key\",\n\t\t\t\t\"network_vxlan_ttl\",\n\t\t\t\t\"container_incremental_copy\",\n\t\t\t\t\"usb_optional_vendorid\",\n\t\t\t\t\"snapshot_scheduling\",\n\t\t\t\t\"snapshot_schedule_aliases\",\n\t\t\t\t\"container_copy_project\",\n\t\t\t\t\"clustering_server_address\",\n\t\t\t\t\"clustering_image_replication\",\n\t\t\t\t\"container_protection_shift\",\n\t\t\t\t\"snapshot_expiry\",\n\t\t\t\t\"container_backup_override_pool\",\n\t\t\t\t\"snapshot_expiry_creation\",\n\t\t\t\t\"network_leases_location\",\n\t\t\t\t\"resources_cpu_socket\",\n\t\t\t\t\"resources_gpu\",\n\t\t\t\t\"resources_numa\",\n\t\t\t\t\"kernel_features\",\n\t\t\t\t\"id_map_current\",\n\t\t\t\t\"event_location\",\n\t\t\t\t\"storage_api_remote_volume_snapshots\",\n\t\t\t\t\"network_nat_address\",\n\t\t\t\t\"container_nic_routes\",\n\t\t\t\t\"rbac\",\n\t\t\t\t\"cluster_internal_copy\",\n\t\t\t\t\"seccomp_notify\",\n\t\t\t\t\"lxc_features\",\n\t\t\t\t\"container_nic_ipvlan\",\n\t\t\t\t\"network_vlan_sriov\",\n\t\t\t\t\"storage_cephfs\",\n\t\t\t\t\"container_nic_ipfilter\",\n\t\t\t\t\"resources_v2\",\n\t\t\t\t\"container_exec_user_group_cwd\",\n\t\t\t\t\"container_syscall_intercept\",\n\t\t\t\t\"container_disk_shift\",\n\t\t\t\t\"storage_shifted\",\n\t\t\t\t\"resources_infiniband\",\n\t\t\t\t\"daemon_storage\",\n\t\t\t\t\"instances\",\n\t\t\t\t\"image_types\",\n\t\t\t\t\"resources_disk_sata\",\n\t\t\t\t\"clustering_roles\",\n\t\t\t\t\"images_expiry\",\n\t\t\t\t\"resources_network_firmware\",\n\t\t\t\t\"backup_compression_algorithm\",\n\t\t\t\t\"ceph_data_pool_name\",\n\t\t\t\t\"container_syscall_intercept_mount\",\n\t\t\t\t\"compression_squashfs\",\n\t\t\t\t\"container_raw_mount\",\n\t\t\t\t\"container_nic_routed\",\n\t\t\t\t\"container_syscall_intercept_mount_fuse\",\n\t\t\t\t\"container_disk_ceph\",\n\t\t\t\t\"virtual-machines\",\n\t\t\t\t\"image_profiles\",\n\t\t\t\t\"clustering_architecture\",\n\t\t\t\t\"resources_disk_id\",\n\t\t\t\t\"storage_lvm_stripes\",\n\t\t\t\t\"vm_boot_priority\",\n\t\t\t\t\"unix_hotplug_devices\",\n\t\t\t\t\"api_filtering\",\n\t\t\t\t\"instance_nic_network\",\n\t\t\t\t\"clustering_sizing\",\n\t\t\t\t\"firewall_driver\",\n\t\t\t\t\"projects_limits\",\n\t\t\t\t\"container_syscall_intercept_hugetlbfs\",\n\t\t\t\t\"limits_hugepages\",\n\t\t\t\t\"container_nic_routed_gateway\",\n\t\t\t\t\"projects_restrictions\",\n\t\t\t\t\"custom_volume_snapshot_expiry\",\n\t\t\t\t\"volume_snapshot_scheduling\",\n\t\t\t\t\"trust_ca_certificates\",\n\t\t\t\t\"snapshot_disk_usage\",\n\t\t\t\t\"clustering_edit_roles\",\n\t\t\t\t\"container_nic_routed_host_address\",\n\t\t\t\t\"container_nic_ipvlan_gateway\",\n\t\t\t\t\"resources_usb_pci\",\n\t\t\t\t\"resources_cpu_threads_numa\",\n\t\t\t\t\"resources_cpu_core_die\",\n\t\t\t\t\"api_os\",\n\t\t\t\t\"container_nic_routed_host_table\",\n\t\t\t\t\"container_nic_ipvlan_host_table\",\n\t\t\t\t\"container_nic_ipvlan_mode\",\n\t\t\t\t\"resources_system\",\n\t\t\t\t\"images_push_relay\",\n\t\t\t\t\"network_dns_search\",\n\t\t\t\t\"container_nic_routed_limits\",\n\t\t\t\t\"instance_nic_bridged_vlan\",\n\t\t\t\t\"network_state_bond_bridge\",\n\t\t\t\t\"usedby_consistency\",\n\t\t\t\t\"custom_block_volumes\",\n\t\t\t\t\"clustering_failure_domains\",\n\t\t\t\t\"resources_gpu_mdev\",\n\t\t\t\t\"console_vga_type\",\n\t\t\t\t\"projects_limits_disk\",\n\t\t\t\t\"network_type_macvlan\",\n\t\t\t\t\"network_type_sriov\",\n\t\t\t\t\"container_syscall_intercept_bpf_devices\",\n\t\t\t\t\"network_type_ovn\",\n\t\t\t\t\"projects_networks\",\n\t\t\t\t\"projects_networks_restricted_uplinks\",\n\t\t\t\t\"custom_volume_backup\",\n\t\t\t\t\"backup_override_name\",\n\t\t\t\t\"storage_rsync_compression\",\n\t\t\t\t\"network_type_physical\",\n\t\t\t\t\"network_ovn_external_subnets\",\n\t\t\t\t\"network_ovn_nat\",\n\t\t\t\t\"network_ovn_external_routes_remove\",\n\t\t\t\t\"tpm_device_type\",\n\t\t\t\t\"storage_zfs_clone_copy_rebase\",\n\t\t\t\t\"gpu_mdev\",\n\t\t\t\t\"resources_pci_iommu\",\n\t\t\t\t\"resources_network_usb\",\n\t\t\t\t\"resources_disk_address\",\n\t\t\t\t\"network_physical_ovn_ingress_mode\",\n\t\t\t\t\"network_ovn_dhcp\",\n\t\t\t\t\"network_physical_routes_anycast\",\n\t\t\t\t\"projects_limits_instances\",\n\t\t\t\t\"network_state_vlan\",\n\t\t\t\t\"instance_nic_bridged_port_isolation\",\n\t\t\t\t\"instance_bulk_state_change\",\n\t\t\t\t\"network_gvrp\",\n\t\t\t\t\"instance_pool_move\",\n\t\t\t\t\"gpu_sriov\",\n\t\t\t\t\"pci_device_type\",\n\t\t\t\t\"storage_volume_state\",\n\t\t\t\t\"network_acl\",\n\t\t\t\t\"migration_stateful\",\n\t\t\t\t\"disk_state_quota\",\n\t\t\t\t\"storage_ceph_features\",\n\t\t\t\t\"projects_compression\",\n\t\t\t\t\"projects_images_remote_cache_expiry\",\n\t\t\t\t\"certificate_project\",\n\t\t\t\t\"network_ovn_acl\",\n\t\t\t\t\"projects_images_auto_update\",\n\t\t\t\t\"projects_restricted_cluster_target\",\n\t\t\t\t\"images_default_architecture\",\n\t\t\t\t\"network_ovn_acl_defaults\",\n\t\t\t\t\"gpu_mig\",\n\t\t\t\t\"project_usage\",\n\t\t\t\t\"network_bridge_acl\",\n\t\t\t\t\"warnings\",\n\t\t\t\t\"projects_restricted_backups_and_snapshots\",\n\t\t\t\t\"clustering_join_token\",\n\t\t\t\t\"clustering_description\",\n\t\t\t\t\"server_trusted_proxy\",\n\t\t\t\t\"clustering_update_cert\",\n\t\t\t\t\"storage_api_project\",\n\t\t\t\t\"server_instance_driver_operational\",\n\t\t\t\t\"server_supported_storage_drivers\",\n\t\t\t\t\"event_lifecycle_requestor_address\",\n\t\t\t\t\"resources_gpu_usb\",\n\t\t\t\t\"clustering_evacuation\",\n\t\t\t\t\"network_ovn_nat_address\",\n\t\t\t\t\"network_bgp\",\n\t\t\t\t\"network_forward\",\n\t\t\t\t\"custom_volume_refresh\",\n\t\t\t\t\"network_counters_errors_dropped\",\n\t\t\t\t\"metrics\",\n\t\t\t\t\"image_source_project\",\n\t\t\t\t\"clustering_config\",\n\t\t\t\t\"network_peer\",\n\t\t\t\t\"linux_sysctl\",\n\t\t\t\t\"network_dns\",\n\t\t\t\t\"ovn_nic_acceleration\",\n\t\t\t\t\"certificate_self_renewal\",\n\t\t\t\t\"instance_project_move\",\n\t\t\t\t\"storage_volume_project_move\",\n\t\t\t\t\"cloud_init\",\n\t\t\t\t\"network_dns_nat\",\n\t\t\t\t\"database_leader\",\n\t\t\t\t\"instance_all_projects\",\n\t\t\t\t\"clustering_groups\",\n\t\t\t\t\"ceph_rbd_du\",\n\t\t\t\t\"instance_get_full\",\n\t\t\t\t\"qemu_metrics\",\n\t\t\t\t\"gpu_mig_uuid\",\n\t\t\t\t\"event_project\",\n\t\t\t\t\"clustering_evacuation_live\",\n\t\t\t\t\"instance_allow_inconsistent_copy\"\n\t\t\t],\n\t\t\t\"api_status\":
    \"stable\",\n\t\t\t\"api_version\": \"1.0\",\n\t\t\t\"auth\": \"trusted\",\n\t\t\t\"public\":
    false,\n\t\t\t\"auth_methods\": [\n\t\t\t\t\"tls\"\n\t\t\t],\n\t\t\t\"environment\":
    {\n\t\t\t\t\"addresses\": [\n\t\t\t\t\t\"10.0.1.30:8443\"\n\t\t\t\t],\n\t\t\t\t\"architectures\":
    [\n\t\t\t\t\t\"x86_64\",\n\t\t\t\t\t\"i686\"\n\t\t\t\t],\n\t\t\t\t\"certificate\":
    \"-----BEGIN CERTIFICATE-----\\nMIIB9zCCAX2gAwIBAgIQAKR8eYGnbF+EvD3i0Q2/czAKBggqhkjOPQQDAzAwMRww\\nGgYDVQQKExNsaW51eGNvbnRhaW5lcnMub3JnMRAwDgYDVQQDDAdyb290QG4xMB4X\\nDTIyMDIwMjE4NTEwNloXDTMyMDEzMTE4NTEwNlowMDEcMBoGA1UEChMTbGludXhj\\nb250YWluZXJzLm9yZzEQMA4GA1UEAwwHcm9vdEBuMTB2MBAGByqGSM49AgEGBSuB\\nBAAiA2IABJ92bn9+Zafi3DNlQ1C21Zew9oKMRCZTQUHA2G9U7ZTVqli76qOGUc4n\\nfAcasrnXOGkPP4AmbQYeoZSewuRHi2Tv0sjQBnrKOr1gnNXvFBnKcFYptyRTIf3n\\nCj6d1YF57qNcMFowDgYDVR0PAQH/BAQDAgWgMBMGA1UdJQQMMAoGCCsGAQUFBwMB\\nMAwGA1UdEwEB/wQCMAAwJQYDVR0RBB4wHIICbjGHBH8AAAGHEAAAAAAAAAAAAAAA\\nAAAAAAEwCgYIKoZIzj0EAwMDaAAwZQIxAMFPCl+cVhLJ/wEt+t9VE3dbcIs/qtFV\\nlO3y/FeYBqju1Z1pcW80K/4lL+NU+1ZdiAIwAc6pef1thBUpauxvLUfdikMQbIgX\\n2B07zaER8uITxdN7iWtAz9mmtpqF4H1Yf9HX\\n-----END
    CERTIFICATE-----\\n\",\n\t\t\t\t\"certificate_fingerprint\": \"c1b8cf714ff7381fafa0ebc36f7eeb544b5d2dc14e8cdf35c2cfd762d9ba7e5d\",\n\t\t\t\t\"driver\":
    \"lxc\",\n\t\t\t\t\"driver_version\": \"4.0.11\",\n\t\t\t\t\"firewall\": \"nftables\",\n\t\t\t\t\"kernel\":
    \"Linux\",\n\t\t\t\t\"kernel_architecture\": \"x86_64\",\n\t\t\t\t\"kernel_features\":
    {\n\t\t\t\t\t\"netnsid_getifaddrs\": \"true\",\n\t\t\t\t\t\"seccomp_listener\":
    \"true\",\n\t\t\t\t\t\"seccomp_listener_continue\": \"true\",\n\t\t\t\t\t\"shiftfs\":
    \"false\",\n\t\t\t\t\t\"uevent_injection\": \"true\",\n\t\t\t\t\t\"unpriv_fscaps\":
    \"true\"\n\t\t\t\t},\n\t\t\t\t\"kernel_version\": \"5.4.0-97-generic\",\n\t\t\t\t\"lxc_features\":
    {\n\t\t\t\t\t\"cgroup2\": \"true\",\n\t\t\t\t\t\"core_scheduling\": \"true\",\n\t\t\t\t\t\"devpts_fd\":
    \"true\",\n\t\t\t\t\t\"idmapped_mounts_v2\": \"true\",\n\t\t\t\t\t\"mount_injection_file\":
    \"true\",\n\t\t\t\t\t\"network_gateway_device_route\": \"true\",\n\t\t\t\t\t\"network_ipvlan\":
    \"true\",\n\t\t\t\t\t\"network_l2proxy\": \"true\",\n\t\t\t\t\t\"network_phys_macvlan_mtu\":
    \"true\",\n\t\t\t\t\t\"network_veth_router\": \"true\",\n\t\t\t\t\t\"pidfd\":
    \"true\",\n\t\t\t\t\t\"seccomp_allow_deny_syntax\": \"true\",\n\t\t\t\t\t\"seccomp_notify\":
    \"true\",\n\t\t\t\t\t\"seccomp_proxy_send_notify_fd\": \"true\"\n\t\t\t\t},\n\t\t\t\t\"os_name\":
    \"Ubuntu\",\n\t\t\t\t\"os_version\": \"20.04\",\n\t\t\t\t\"project\": \"default\",\n\t\t\t\t\"server\":
    \"lxd\",\n\t\t\t\t\"server_clustered\": true,\n\t\t\t\t\"server_name\": \"n1\",\n\t\t\t\t\"server_pid\":
    17334,\n\t\t\t\t\"server_version\": \"4.22\",\n\t\t\t\t\"storage\": \"zfs\",\n\t\t\t\t\"storage_version\":
    \"0.8.3-1ubuntu12.13\",\n\t\t\t\t\"storage_supported_drivers\": [\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\":
    \"zfs\",\n\t\t\t\t\t\t\"Version\": \"0.8.3-1ubuntu12.13\",\n\t\t\t\t\t\t\"Remote\":
    false\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\": \"ceph\",\n\t\t\t\t\t\t\"Version\":
    \"15.2.14\",\n\t\t\t\t\t\t\"Remote\": true\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\":
    \"btrfs\",\n\t\t\t\t\t\t\"Version\": \"5.4.1\",\n\t\t\t\t\t\t\"Remote\": false\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\":
    \"cephfs\",\n\t\t\t\t\t\t\"Version\": \"15.2.14\",\n\t\t\t\t\t\t\"Remote\": true\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\":
    \"dir\",\n\t\t\t\t\t\t\"Version\": \"1\",\n\t\t\t\t\t\t\"Remote\": false\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t\"Name\":
    \"lvm\",\n\t\t\t\t\t\t\"Version\": \"2.03.07(2) (2019-11-30) / 1.02.167 (2019-11-30)
    / 4.41.0\",\n\t\t\t\t\t\t\"Remote\": false\n\t\t\t\t\t}\n\t\t\t\t]\n\t\t\t}\n\t\t}\n\t}"
timestamp: "2022-02-03T01:50:01.311543271+01:00"
type: logging


location: n1
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0/events?target=n2
    username: root
  level: dbug
  message: Handling API request
timestamp: "2022-02-03T01:50:01.318885637+01:00"
type: logging


location: n1
metadata:
  context:
    listener: 13742aa1-07e6-46de-a9e3-a4ddf84e59db
    local: /var/snap/lxd/common/lxd/unix.socket
    localOnly: "false"
    remote: '@'
  level: dbug
  message: Event listener server handler started
timestamp: "2022-02-03T01:50:01.319736892+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: 'New task Operation: 0d5ac0d2-fe94-47d2-a236-36583bf0fa67'
timestamp: "2022-02-03T01:50:01.333336258+01:00"
type: logging


location: n1
metadata:
  class: task
  created_at: "2022-02-03T01:50:01.327001709+01:00"
  description: Migrating instance
  err: ""
  id: 0d5ac0d2-fe94-47d2-a236-36583bf0fa67
  location: n1
  may_cancel: false
  metadata: null
  resources:
    containers:
    - /1.0/containers/test1
    instances:
    - /1.0/instances/test1
  status: Pending
  status_code: 105
  updated_at: "2022-02-03T01:50:01.327001709+01:00"
project: default
timestamp: "2022-02-03T01:50:01.334451672+01:00"
type: operation


location: n1
metadata:
  context: {}
  level: dbug
  message: 'Started task operation: 0d5ac0d2-fe94-47d2-a236-36583bf0fa67'
timestamp: "2022-02-03T01:50:01.334626898+01:00"
type: logging


location: n1
metadata:
  class: task
  created_at: "2022-02-03T01:50:01.327001709+01:00"
  description: Migrating instance
  err: ""
  id: 0d5ac0d2-fe94-47d2-a236-36583bf0fa67
  location: n1
  may_cancel: false
  metadata: null
  resources:
    containers:
    - /1.0/containers/test1
    instances:
    - /1.0/instances/test1
  status: Running
  status_code: 103
  updated_at: "2022-02-03T01:50:01.327001709+01:00"
project: default
timestamp: "2022-02-03T01:50:01.336252638+01:00"
type: operation


location: n1
metadata:
  context:
    http_code: "202"
  level: dbug
  message: "WriteJSON\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/0d5ac0d2-fe94-47d2-a236-36583bf0fa67\",\n\t\t\"error_code\":
    0,\n\t\t\"error\": \"\",\n\t\t\"metadata\": {\n\t\t\t\"id\": \"0d5ac0d2-fe94-47d2-a236-36583bf0fa67\",\n\t\t\t\"class\":
    \"task\",\n\t\t\t\"description\": \"Migrating instance\",\n\t\t\t\"created_at\":
    \"2022-02-03T01:50:01.327001709+01:00\",\n\t\t\t\"updated_at\": \"2022-02-03T01:50:01.327001709+01: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/containers/test1\"\n\t\t\t\t],\n\t\t\t\t\"instances\": [\n\t\t\t\t\t\"/1.0/instances/test1\"\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\":
    \"n1\"\n\t\t}\n\t}"
timestamp: "2022-02-03T01:50:01.339650186+01:00"
type: logging


location: n1
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0/operations/0d5ac0d2-fe94-47d2-a236-36583bf0fa67?target=n2
    username: root
  level: dbug
  message: Handling API request
timestamp: "2022-02-03T01:50:01.344191509+01:00"
type: logging


location: n1
metadata:
  context:
    http_code: "200"
  level: dbug
  message: "WriteJSON\n\t{\n\t\t\"type\": \"sync\",\n\t\t\"status\": \"Success\",\n\t\t\"status_code\":
    200,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\":
    {\n\t\t\t\"id\": \"0d5ac0d2-fe94-47d2-a236-36583bf0fa67\",\n\t\t\t\"class\": \"task\",\n\t\t\t\"description\":
    \"Migrating instance\",\n\t\t\t\"created_at\": \"2022-02-03T01:50:01.327001709+01:00\",\n\t\t\t\"updated_at\":
    \"2022-02-03T01:50:01.327001709+01: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/containers/test1\"\n\t\t\t\t],\n\t\t\t\t\"instances\":
    [\n\t\t\t\t\t\"/1.0/instances/test1\"\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\":
    \"n1\"\n\t\t}\n\t}"
timestamp: "2022-02-03T01:50:01.346445227+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: Connecting to a remote LXD over HTTPS
timestamp: "2022-02-03T01:50:01.350767487+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: Connecting to a remote LXD over HTTPS
timestamp: "2022-02-03T01:50:01.357700286+01:00"
type: logging


location: n1
metadata:
  context:
    etag: ""
    method: GET
    url: https://10.0.1.30:8443/1.0/instances/test1?project=default
  level: dbug
  message: Sending request to LXD
timestamp: "2022-02-03T01:50:01.363945653+01:00"
type: logging


location: n1
metadata:
  context:
    fingerprint: 02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf
    subject: CN=root@n1,O=linuxcontainers.org
  level: dbug
  message: Matched trusted cert
timestamp: "2022-02-03T01:50:01.398163787+01:00"
type: logging


location: n1
metadata:
  context:
    ip: 10.0.1.30:34200
    method: GET
    protocol: cluster
    url: /1.0/instances/test1?project=default
    username: ""
  level: dbug
  message: Handling API request
timestamp: "2022-02-03T01:50:01.398319767+01:00"
type: logging


location: n1
metadata:
  context:
    http_code: "200"
  level: dbug
  message: "WriteJSON\n\t{\n\t\t\"type\": \"sync\",\n\t\t\"status\": \"Success\",\n\t\t\"status_code\":
    200,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\":
    {\n\t\t\t\"architecture\": \"x86_64\",\n\t\t\t\"config\": {\n\t\t\t\t\"image.architecture\":
    \"amd64\",\n\t\t\t\t\"image.description\": \"Alpine edge amd64 (20220201_13:00)\",\n\t\t\t\t\"image.os\":
    \"Alpine\",\n\t\t\t\t\"image.release\": \"edge\",\n\t\t\t\t\"image.serial\": \"20220201_13:00\",\n\t\t\t\t\"image.type\":
    \"squashfs\",\n\t\t\t\t\"image.variant\": \"default\",\n\t\t\t\t\"volatile.base_image\":
    \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\t\"volatile.eth0.hwaddr\":
    \"00:16:3e:2f:90:a7\",\n\t\t\t\t\"volatile.idmap.base\": \"0\",\n\t\t\t\t\"volatile.idmap.current\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.idmap.next\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.last_state.idmap\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.last_state.power\":
    \"STOPPED\",\n\t\t\t\t\"volatile.uuid\": \"3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t},\n\t\t\t\"devices\":
    {},\n\t\t\t\"ephemeral\": false,\n\t\t\t\"profiles\": [\n\t\t\t\t\"default\"\n\t\t\t],\n\t\t\t\"stateful\":
    false,\n\t\t\t\"description\": \"\",\n\t\t\t\"created_at\": \"2022-02-03T00:49:12.408276688Z\",\n\t\t\t\"expanded_config\":
    {\n\t\t\t\t\"image.architecture\": \"amd64\",\n\t\t\t\t\"image.description\":
    \"Alpine edge amd64 (20220201_13:00)\",\n\t\t\t\t\"image.os\": \"Alpine\",\n\t\t\t\t\"image.release\":
    \"edge\",\n\t\t\t\t\"image.serial\": \"20220201_13:00\",\n\t\t\t\t\"image.type\":
    \"squashfs\",\n\t\t\t\t\"image.variant\": \"default\",\n\t\t\t\t\"volatile.base_image\":
    \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\t\"volatile.eth0.hwaddr\":
    \"00:16:3e:2f:90:a7\",\n\t\t\t\t\"volatile.idmap.base\": \"0\",\n\t\t\t\t\"volatile.idmap.current\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.idmap.next\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.last_state.idmap\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\t\"volatile.last_state.power\":
    \"STOPPED\",\n\t\t\t\t\"volatile.uuid\": \"3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t},\n\t\t\t\"expanded_devices\":
    {\n\t\t\t\t\"eth0\": {\n\t\t\t\t\t\"name\": \"eth0\",\n\t\t\t\t\t\"nictype\":
    \"macvlan\",\n\t\t\t\t\t\"parent\": \"enp5s0\",\n\t\t\t\t\t\"type\": \"nic\"\n\t\t\t\t},\n\t\t\t\t\"root\":
    {\n\t\t\t\t\t\"path\": \"/\",\n\t\t\t\t\t\"pool\": \"local\",\n\t\t\t\t\t\"type\":
    \"disk\"\n\t\t\t\t}\n\t\t\t},\n\t\t\t\"name\": \"test1\",\n\t\t\t\"status\": \"Stopped\",\n\t\t\t\"status_code\":
    102,\n\t\t\t\"last_used_at\": \"1970-01-01T00:00:00Z\",\n\t\t\t\"location\": \"n1\",\n\t\t\t\"type\":
    \"container\",\n\t\t\t\"project\": \"default\"\n\t\t}\n\t}"
timestamp: "2022-02-03T01:50:01.405255214+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: Got response struct from LXD
timestamp: "2022-02-03T01:50:01.406755029+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: "\n\t{\n\t\t\"architecture\": \"x86_64\",\n\t\t\"config\": {\n\t\t\t\"image.architecture\":
    \"amd64\",\n\t\t\t\"image.description\": \"Alpine edge amd64 (20220201_13:00)\",\n\t\t\t\"image.os\":
    \"Alpine\",\n\t\t\t\"image.release\": \"edge\",\n\t\t\t\"image.serial\": \"20220201_13:00\",\n\t\t\t\"image.type\":
    \"squashfs\",\n\t\t\t\"image.variant\": \"default\",\n\t\t\t\"volatile.base_image\":
    \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\"volatile.eth0.hwaddr\":
    \"00:16:3e:2f:90:a7\",\n\t\t\t\"volatile.idmap.base\": \"0\",\n\t\t\t\"volatile.idmap.current\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.idmap.next\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.idmap\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.power\":
    \"STOPPED\",\n\t\t\t\"volatile.uuid\": \"3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t},\n\t\t\"devices\":
    {},\n\t\t\"ephemeral\": false,\n\t\t\"profiles\": [\n\t\t\t\"default\"\n\t\t],\n\t\t\"stateful\":
    false,\n\t\t\"description\": \"\",\n\t\t\"created_at\": \"2022-02-03T00:49:12.408276688Z\",\n\t\t\"expanded_config\":
    {\n\t\t\t\"image.architecture\": \"amd64\",\n\t\t\t\"image.description\": \"Alpine
    edge amd64 (20220201_13:00)\",\n\t\t\t\"image.os\": \"Alpine\",\n\t\t\t\"image.release\":
    \"edge\",\n\t\t\t\"image.serial\": \"20220201_13:00\",\n\t\t\t\"image.type\":
    \"squashfs\",\n\t\t\t\"image.variant\": \"default\",\n\t\t\t\"volatile.base_image\":
    \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\"volatile.eth0.hwaddr\":
    \"00:16:3e:2f:90:a7\",\n\t\t\t\"volatile.idmap.base\": \"0\",\n\t\t\t\"volatile.idmap.current\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.idmap.next\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.idmap\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.power\":
    \"STOPPED\",\n\t\t\t\"volatile.uuid\": \"3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t},\n\t\t\"expanded_devices\":
    {\n\t\t\t\"eth0\": {\n\t\t\t\t\"name\": \"eth0\",\n\t\t\t\t\"nictype\": \"macvlan\",\n\t\t\t\t\"parent\":
    \"enp5s0\",\n\t\t\t\t\"type\": \"nic\"\n\t\t\t},\n\t\t\t\"root\": {\n\t\t\t\t\"path\":
    \"/\",\n\t\t\t\t\"pool\": \"local\",\n\t\t\t\t\"type\": \"disk\"\n\t\t\t}\n\t\t},\n\t\t\"name\":
    \"test1\",\n\t\t\"status\": \"Stopped\",\n\t\t\"status_code\": 102,\n\t\t\"last_used_at\":
    \"1970-01-01T00:00:00Z\",\n\t\t\"location\": \"n1\",\n\t\t\"type\": \"container\",\n\t\t\"project\":
    \"default\"\n\t}"
timestamp: "2022-02-03T01:50:01.40700872+01:00"
type: logging


location: n1
metadata:
  context:
    fingerprint: 02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf
    subject: CN=root@n1,O=linuxcontainers.org
  level: dbug
  message: Matched trusted cert
timestamp: "2022-02-03T01:50:01.435401269+01:00"
type: logging


location: n1
metadata:
  context:
    ip: 10.0.1.30:34202
    method: GET
    protocol: cluster
    url: /1.0/events?project=default
    username: ""
  level: dbug
  message: Handling API request
timestamp: "2022-02-03T01:50:01.435565049+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: 'Connected to the websocket: wss://10.0.1.30:8443/1.0/events?project=default'
timestamp: "2022-02-03T01:50:01.440983317+01:00"
type: logging


location: n1
metadata:
  context:
    etag: ""
    method: POST
    url: https://10.0.1.30:8443/1.0/instances/test1?project=default
  level: dbug
  message: Sending request to LXD
timestamp: "2022-02-03T01:50:01.441240211+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: "\n\t{\n\t\t\"name\": \"\",\n\t\t\"migration\": true,\n\t\t\"live\": false,\n\t\t\"instance_only\":
    false,\n\t\t\"container_only\": false,\n\t\t\"target\": null,\n\t\t\"pool\": \"\",\n\t\t\"project\":
    \"\"\n\t}"
timestamp: "2022-02-03T01:50:01.441451751+01:00"
type: logging


location: n1
metadata:
  context:
    listener: 97d1571a-2f1a-4917-8f01-310c1c74da13
    local: 10.0.1.30:8443
    localOnly: "true"
    remote: 10.0.1.30:34202
  level: dbug
  message: Event listener server handler started
timestamp: "2022-02-03T01:50:01.472213182+01:00"
type: logging


location: n1
metadata:
  context:
    fingerprint: 02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf
    subject: CN=root@n1,O=linuxcontainers.org
  level: dbug
  message: Matched trusted cert
timestamp: "2022-02-03T01:50:01.473821177+01:00"
type: logging


location: n1
metadata:
  context:
    ip: 10.0.1.30:34204
    method: POST
    protocol: cluster
    url: /1.0/instances/test1?project=default
    username: ""
  level: dbug
  message: Handling API request
timestamp: "2022-02-03T01:50:01.473952024+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: 'New websocket Operation: 23b1ec3f-d589-4099-b4bd-e2228cce50d1'
timestamp: "2022-02-03T01:50:01.483784046+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: 'Started websocket operation: 23b1ec3f-d589-4099-b4bd-e2228cce50d1'
timestamp: "2022-02-03T01:50:01.48511754+01:00"
type: logging


location: n1
metadata:
  class: websocket
  created_at: "2022-02-03T01:50:01.478644322+01:00"
  description: Migrating instance
  err: ""
  id: 23b1ec3f-d589-4099-b4bd-e2228cce50d1
  location: n1
  may_cancel: true
  metadata:
    control: f8bc945622d87421d5034a11d613d383274c30c24e7aff92e88f18c5ba3f111e
    fs: 7b4f1d5c7c6f8779f5b6dc8d3ba0f3bcface77f9d6a9e010b31a0cd7fab40e90
  resources:
    containers:
    - /1.0/containers/test1
    instances:
    - /1.0/instances/test1
  status: Pending
  status_code: 105
  updated_at: "2022-02-03T01:50:01.478644322+01:00"
project: default
timestamp: "2022-02-03T01:50:01.484937455+01:00"
type: operation


location: n1
metadata:
  context: {}
  level: info
  message: Waiting for migration channel connections
timestamp: "2022-02-03T01:50:01.486251418+01:00"
type: logging


location: n1
metadata:
  class: websocket
  created_at: "2022-02-03T01:50:01.478644322+01:00"
  description: Migrating instance
  err: ""
  id: 23b1ec3f-d589-4099-b4bd-e2228cce50d1
  location: n1
  may_cancel: true
  metadata:
    control: f8bc945622d87421d5034a11d613d383274c30c24e7aff92e88f18c5ba3f111e
    fs: 7b4f1d5c7c6f8779f5b6dc8d3ba0f3bcface77f9d6a9e010b31a0cd7fab40e90
  resources:
    containers:
    - /1.0/containers/test1
    instances:
    - /1.0/instances/test1
  status: Running
  status_code: 103
  updated_at: "2022-02-03T01:50:01.478644322+01:00"
project: default
timestamp: "2022-02-03T01:50:01.487515771+01:00"
type: operation


location: n1
metadata:
  context:
    http_code: "202"
  level: dbug
  message: "WriteJSON\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/23b1ec3f-d589-4099-b4bd-e2228cce50d1\",\n\t\t\"error_code\":
    0,\n\t\t\"error\": \"\",\n\t\t\"metadata\": {\n\t\t\t\"id\": \"23b1ec3f-d589-4099-b4bd-e2228cce50d1\",\n\t\t\t\"class\":
    \"websocket\",\n\t\t\t\"description\": \"Migrating instance\",\n\t\t\t\"created_at\":
    \"2022-02-03T01:50:01.478644322+01:00\",\n\t\t\t\"updated_at\": \"2022-02-03T01:50:01.478644322+01: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/containers/test1\"\n\t\t\t\t],\n\t\t\t\t\"instances\": [\n\t\t\t\t\t\"/1.0/instances/test1\"\n\t\t\t\t]\n\t\t\t},\n\t\t\t\"metadata\":
    {\n\t\t\t\t\"control\": \"f8bc945622d87421d5034a11d613d383274c30c24e7aff92e88f18c5ba3f111e\",\n\t\t\t\t\"fs\":
    \"7b4f1d5c7c6f8779f5b6dc8d3ba0f3bcface77f9d6a9e010b31a0cd7fab40e90\"\n\t\t\t},\n\t\t\t\"may_cancel\":
    true,\n\t\t\t\"err\": \"\",\n\t\t\t\"location\": \"n1\"\n\t\t}\n\t}"
timestamp: "2022-02-03T01:50:01.488669285+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: Got operation from LXD
timestamp: "2022-02-03T01:50:01.48970458+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: "\n\t{\n\t\t\"id\": \"23b1ec3f-d589-4099-b4bd-e2228cce50d1\",\n\t\t\"class\":
    \"websocket\",\n\t\t\"description\": \"Migrating instance\",\n\t\t\"created_at\":
    \"2022-02-03T01:50:01.478644322+01:00\",\n\t\t\"updated_at\": \"2022-02-03T01:50:01.478644322+01:00\",\n\t\t\"status\":
    \"Running\",\n\t\t\"status_code\": 103,\n\t\t\"resources\": {\n\t\t\t\"containers\":
    [\n\t\t\t\t\"/1.0/containers/test1\"\n\t\t\t],\n\t\t\t\"instances\": [\n\t\t\t\t\"/1.0/instances/test1\"\n\t\t\t]\n\t\t},\n\t\t\"metadata\":
    {\n\t\t\t\"control\": \"f8bc945622d87421d5034a11d613d383274c30c24e7aff92e88f18c5ba3f111e\",\n\t\t\t\"fs\":
    \"7b4f1d5c7c6f8779f5b6dc8d3ba0f3bcface77f9d6a9e010b31a0cd7fab40e90\"\n\t\t},\n\t\t\"may_cancel\":
    true,\n\t\t\"err\": \"\",\n\t\t\"location\": \"n1\"\n\t}"
timestamp: "2022-02-03T01:50:01.489853177+01:00"
type: logging


location: n2
metadata:
  context:
    fingerprint: 02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf
    subject: CN=root@n1,O=linuxcontainers.org
  level: dbug
  message: Matched trusted cert
timestamp: "2022-02-03T01:50:01.774097099+01:00"
type: logging


location: n2
metadata:
  context:
    ip: 10.0.1.30:37690
    method: GET
    protocol: cluster
    url: /1.0/events?project=default&target=n2
    username: ""
  level: dbug
  message: Handling API request
timestamp: "2022-02-03T01:50:01.774975187+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: 'Connected to the websocket: wss://10.0.1.31:8443/1.0/events?project=default&target=n2'
timestamp: "2022-02-03T01:50:02.375912238+01:00"
type: logging


location: n1
metadata:
  context:
    etag: ""
    method: POST
    url: https://10.0.1.31:8443/1.0/instances?project=default&target=n2
  level: dbug
  message: Sending request to LXD
timestamp: "2022-02-03T01:50:02.376896748+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: "\n\t{\n\t\t\"architecture\": \"x86_64\",\n\t\t\"config\": {\n\t\t\t\"image.architecture\":
    \"amd64\",\n\t\t\t\"image.description\": \"Alpine edge amd64 (20220201_13:00)\",\n\t\t\t\"image.os\":
    \"Alpine\",\n\t\t\t\"image.release\": \"edge\",\n\t\t\t\"image.serial\": \"20220201_13:00\",\n\t\t\t\"image.type\":
    \"squashfs\",\n\t\t\t\"image.variant\": \"default\",\n\t\t\t\"volatile.base_image\":
    \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\"volatile.eth0.hwaddr\":
    \"00:16:3e:2f:90:a7\",\n\t\t\t\"volatile.idmap.base\": \"0\",\n\t\t\t\"volatile.idmap.current\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.idmap.next\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.idmap\":
    \"[{\\\"Isuid\\\":true,\\\"Isgid\\\":false,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000},{\\\"Isuid\\\":false,\\\"Isgid\\\":true,\\\"Hostid\\\":1000000,\\\"Nsid\\\":0,\\\"Maprange\\\":1000000000}]\",\n\t\t\t\"volatile.last_state.power\":
    \"STOPPED\",\n\t\t\t\"volatile.uuid\": \"3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t},\n\t\t\"devices\":
    {},\n\t\t\"ephemeral\": false,\n\t\t\"profiles\": [\n\t\t\t\"default\"\n\t\t],\n\t\t\"stateful\":
    false,\n\t\t\"description\": \"\",\n\t\t\"name\": \"lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\",\n\t\t\"source\":
    {\n\t\t\t\"type\": \"migration\",\n\t\t\t\"certificate\": \"-----BEGIN CERTIFICATE-----\\nMIIB9zCCAX2gAwIBAgIQAKR8eYGnbF+EvD3i0Q2/czAKBggqhkjOPQQDAzAwMRww\\nGgYDVQQKExNsaW51eGNvbnRhaW5lcnMub3JnMRAwDgYDVQQDDAdyb290QG4xMB4X\\nDTIyMDIwMjE4NTEwNloXDTMyMDEzMTE4NTEwNlowMDEcMBoGA1UEChMTbGludXhj\\nb250YWluZXJzLm9yZzEQMA4GA1UEAwwHcm9vdEBuMTB2MBAGByqGSM49AgEGBSuB\\nBAAiA2IABJ92bn9+Zafi3DNlQ1C21Zew9oKMRCZTQUHA2G9U7ZTVqli76qOGUc4n\\nfAcasrnXOGkPP4AmbQYeoZSewuRHi2Tv0sjQBnrKOr1gnNXvFBnKcFYptyRTIf3n\\nCj6d1YF57qNcMFowDgYDVR0PAQH/BAQDAgWgMBMGA1UdJQQMMAoGCCsGAQUFBwMB\\nMAwGA1UdEwEB/wQCMAAwJQYDVR0RBB4wHIICbjGHBH8AAAGHEAAAAAAAAAAAAAAA\\nAAAAAAEwCgYIKoZIzj0EAwMDaAAwZQIxAMFPCl+cVhLJ/wEt+t9VE3dbcIs/qtFV\\nlO3y/FeYBqju1Z1pcW80K/4lL+NU+1ZdiAIwAc6pef1thBUpauxvLUfdikMQbIgX\\n2B07zaER8uITxdN7iWtAz9mmtpqF4H1Yf9HX\\n-----END
    CERTIFICATE-----\\n\",\n\t\t\t\"base-image\": \"859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee\",\n\t\t\t\"mode\":
    \"pull\",\n\t\t\t\"operation\": \"https://10.0.1.30:8443/1.0/operations/23b1ec3f-d589-4099-b4bd-e2228cce50d1\",\n\t\t\t\"secrets\":
    {\n\t\t\t\t\"control\": \"f8bc945622d87421d5034a11d613d383274c30c24e7aff92e88f18c5ba3f111e\",\n\t\t\t\t\"fs\":
    \"7b4f1d5c7c6f8779f5b6dc8d3ba0f3bcface77f9d6a9e010b31a0cd7fab40e90\"\n\t\t\t},\n\t\t\t\"allow_inconsistent\":
    false\n\t\t},\n\t\t\"instance_type\": \"\",\n\t\t\"type\": \"container\"\n\t}"
timestamp: "2022-02-03T01:50:02.37857399+01:00"
type: logging


location: n2
metadata:
  context:
    listener: 41f6223b-5af7-4bf0-b0be-b076f7168554
    local: 10.0.1.31:8443
    localOnly: "false"
    remote: 10.0.1.30:37690
  level: dbug
  message: Event listener server handler started
timestamp: "2022-02-03T01:50:02.534310477+01:00"
type: logging


location: n2
metadata:
  context:
    fingerprint: 02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf
    subject: CN=root@n1,O=linuxcontainers.org
  level: dbug
  message: Matched trusted cert
timestamp: "2022-02-03T01:50:02.697439381+01:00"
type: logging


location: n2
metadata:
  context: {}
  level: dbug
  message: Responding to instance create
timestamp: "2022-02-03T01:50:02.700680878+01:00"
type: logging


location: n2
metadata:
  context:
    ip: 10.0.1.30:37692
    method: POST
    protocol: cluster
    url: /1.0/instances?project=default&target=n2
    username: ""
  level: dbug
  message: Handling API request
timestamp: "2022-02-03T01:50:02.698413018+01:00"
type: logging


location: n1
metadata:
  context:
    address: 10.0.1.31:8443
  level: dbug
  message: Sending heartbeat request
timestamp: "2022-02-03T01:50:04.642202278+01:00"
type: logging


location: n2
metadata:
  context:
    raftMembers: '[{{1 10.0.1.30:8443 voter} n1} {{2 10.0.1.31:8443 stand-by} n2}]'
  level: dbug
  message: Replace current raft nodes
timestamp: "2022-02-03T01:50:04.839367303+01:00"
type: logging


location: n2
metadata:
  context:
    fingerprint: 02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf
    subject: CN=root@n1,O=linuxcontainers.org
  level: dbug
  message: Matched trusted cert
timestamp: "2022-02-03T01:50:04.839064567+01:00"
type: logging


location: n1
metadata:
  context:
    remote: 10.0.1.31:8443
  level: dbug
  message: Successful heartbeat
timestamp: "2022-02-03T01:50:04.856363618+01:00"
type: logging


location: n1
metadata:
  context:
    local: 10.0.1.30:8443
  level: dbug
  message: Rebalancing member roles in heartbeat
timestamp: "2022-02-03T01:50:04.870509613+01:00"
type: logging


location: n1
metadata:
  context:
    duration: 6.3295455s
    local: 10.0.1.30:8443
  level: dbug
  message: Completed heartbeat round
timestamp: "2022-02-03T01:50:05.061056888+01:00"
type: logging


location: n2
metadata:
  context:
    action: create
    instance: lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
    project: default
    reusable: "false"
  level: dbug
  message: Instance operation lock created
timestamp: "2022-02-03T01:50:07.800619025+01:00"
type: logging


location: n2
metadata:
  context:
    ephemeral: "false"
    instance: lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
    instanceType: container
    project: default
  level: info
  message: Creating container
timestamp: "2022-02-03T01:50:08.60822079+01:00"
type: logging


location: n1
metadata:
  context:
    local: 10.0.1.30:8443
    mode: normal
  level: dbug
  message: Starting heartbeat round
timestamp: "2022-02-03T01:50:08.707962561+01:00"
type: logging


location: n1
metadata:
  context:
    members: '[{{1 10.0.1.30:8443 voter} n1} {{2 10.0.1.31:8443 stand-by} n2}]'
  level: dbug
  message: Heartbeat updating local raft members
timestamp: "2022-02-03T01:50:08.708963637+01:00"
type: logging


location: n2
metadata:
  context:
    driver: zfs
    instance: lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
    pool: local
    project: default
  level: dbug
  message: FillInstanceConfig started
timestamp: "2022-02-03T01:50:10.412244201+01:00"
type: logging


location: n2
metadata:
  context:
    driver: zfs
    instance: lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
    pool: local
    project: default
  level: dbug
  message: FillInstanceConfig finished
timestamp: "2022-02-03T01:50:10.413071283+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: 'Failure for websocket operation: 23b1ec3f-d589-4099-b4bd-e2228cce50d1:
    Timed out waiting for connections'
timestamp: "2022-02-03T01:50:11.489405249+01:00"
type: logging


location: n1
metadata:
  class: websocket
  created_at: "2022-02-03T01:50:01.478644322+01:00"
  description: Migrating instance
  err: Timed out waiting for connections
  id: 23b1ec3f-d589-4099-b4bd-e2228cce50d1
  location: n1
  may_cancel: false
  metadata:
    control: f8bc945622d87421d5034a11d613d383274c30c24e7aff92e88f18c5ba3f111e
    fs: 7b4f1d5c7c6f8779f5b6dc8d3ba0f3bcface77f9d6a9e010b31a0cd7fab40e90
  resources:
    containers:
    - /1.0/containers/test1
    instances:
    - /1.0/instances/test1
  status: Failure
  status_code: 400
  updated_at: "2022-02-03T01:50:01.478644322+01:00"
project: default
timestamp: "2022-02-03T01:50:11.496343409+01:00"
type: operation


location: n1
metadata:
  context:
    listener: c0b8562a-786f-4057-9f8e-ae8f95542bc5
    local: 10.0.1.30:8443
    localOnly: "false"
    remote: 10.0.1.31:54520
  level: dbug
  message: Event listener server handler stopped
timestamp: "2022-02-03T01:50:12.36965717+01:00"
type: logging


location: n2
metadata:
  context:
    ephemeral: "false"
    instance: lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
    instanceType: container
    project: default
  level: info
  message: Created container
timestamp: "2022-02-03T01:50:12.872036305+01:00"
type: logging


location: n2
metadata:
  action: instance-created
  source: /1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
project: default
timestamp: "2022-02-03T01:50:12.872101871+01:00"
type: lifecycle


location: n2
metadata:
  context: {}
  level: dbug
  message: 'New task Operation: 80c4b992-3cb1-4588-9fcc-b14a58eeec72'
timestamp: "2022-02-03T01:50:13.056765038+01:00"
type: logging


location: n2
metadata:
  class: task
  created_at: "2022-02-03T01:50:12.880337898+01:00"
  description: Creating instance
  err: ""
  id: 80c4b992-3cb1-4588-9fcc-b14a58eeec72
  location: n2
  may_cancel: false
  metadata: null
  resources:
    containers:
    - /1.0/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
    instances:
    - /1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
  status: Pending
  status_code: 105
  updated_at: "2022-02-03T01:50:12.880337898+01:00"
project: default
timestamp: "2022-02-03T01:50:13.179553257+01:00"
type: operation


location: n2
metadata:
  context:
    action: create
    err: <nil>
    instance: lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
    project: default
    reusable: "false"
  level: dbug
  message: Instance operation lock finished
timestamp: "2022-02-03T01:50:13.181189218+01:00"
type: logging


location: n2
metadata:
  context: {}
  level: dbug
  message: 'Started task operation: 80c4b992-3cb1-4588-9fcc-b14a58eeec72'
timestamp: "2022-02-03T01:50:13.182043484+01:00"
type: logging


location: n2
metadata:
  class: task
  created_at: "2022-02-03T01:50:12.880337898+01:00"
  description: Creating instance
  err: ""
  id: 80c4b992-3cb1-4588-9fcc-b14a58eeec72
  location: n2
  may_cancel: false
  metadata: null
  resources:
    containers:
    - /1.0/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
    instances:
    - /1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
  status: Running
  status_code: 103
  updated_at: "2022-02-03T01:50:12.880337898+01:00"
project: default
timestamp: "2022-02-03T01:50:13.320465915+01:00"
type: operation


location: n1
metadata:
  context:
    ip: 10.0.1.31:54534
    url: /1.0/operations/23b1ec3f-d589-4099-b4bd-e2228cce50d1/websocket?secret=f8bc945622d87421d5034a11d613d383274c30c24e7aff92e88f18c5ba3f111e
  level: dbug
  message: Allowing untrusted GET
timestamp: "2022-02-03T01:50:13.334723056+01:00"
type: logging


location: n1
metadata:
  context:
    http_code: "500"
  level: dbug
  message: "Error Response\n\t{\n\t\t\"type\": \"error\",\n\t\t\"status\": \"\",\n\t\t\"status_code\":
    0,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 500,\n\t\t\"error\": \"Only
    running operations can be connected\",\n\t\t\"metadata\": null\n\t}"
timestamp: "2022-02-03T01:50:13.335041694+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: Got operation from LXD
timestamp: "2022-02-03T01:50:13.447399643+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: "\n\t{\n\t\t\"id\": \"80c4b992-3cb1-4588-9fcc-b14a58eeec72\",\n\t\t\"class\":
    \"task\",\n\t\t\"description\": \"Creating instance\",\n\t\t\"created_at\": \"2022-02-03T01:50:12.880337898+01:00\",\n\t\t\"updated_at\":
    \"2022-02-03T01:50:12.880337898+01:00\",\n\t\t\"status\": \"Running\",\n\t\t\"status_code\":
    103,\n\t\t\"resources\": {\n\t\t\t\"containers\": [\n\t\t\t\t\"/1.0/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t],\n\t\t\t\"instances\":
    [\n\t\t\t\t\"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t]\n\t\t},\n\t\t\"metadata\":
    null,\n\t\t\"may_cancel\": false,\n\t\t\"err\": \"\",\n\t\t\"location\": \"n2\"\n\t}"
timestamp: "2022-02-03T01:50:13.447904817+01:00"
type: logging


location: n1
metadata:
  context:
    etag: ""
    method: GET
    url: https://10.0.1.31:8443/1.0/operations/80c4b992-3cb1-4588-9fcc-b14a58eeec72?project=default&target=n2
  level: dbug
  message: Sending request to LXD
timestamp: "2022-02-03T01:50:13.448426019+01:00"
type: logging


location: n2
metadata:
  context:
    http_code: "202"
  level: dbug
  message: "WriteJSON\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/80c4b992-3cb1-4588-9fcc-b14a58eeec72\",\n\t\t\"error_code\":
    0,\n\t\t\"error\": \"\",\n\t\t\"metadata\": {\n\t\t\t\"id\": \"80c4b992-3cb1-4588-9fcc-b14a58eeec72\",\n\t\t\t\"class\":
    \"task\",\n\t\t\t\"description\": \"Creating instance\",\n\t\t\t\"created_at\":
    \"2022-02-03T01:50:12.880337898+01:00\",\n\t\t\t\"updated_at\": \"2022-02-03T01:50:12.880337898+01: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/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t\t],\n\t\t\t\t\"instances\":
    [\n\t\t\t\t\t\"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\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\":
    \"n2\"\n\t\t}\n\t}"
timestamp: "2022-02-03T01:50:13.443962786+01:00"
type: logging


location: n2
metadata:
  context:
    fingerprint: 02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf
    subject: CN=root@n1,O=linuxcontainers.org
  level: dbug
  message: Matched trusted cert
timestamp: "2022-02-03T01:50:13.845555107+01:00"
type: logging


location: n2
metadata:
  context:
    ip: 10.0.1.30:37700
    method: GET
    protocol: cluster
    url: /1.0/operations/80c4b992-3cb1-4588-9fcc-b14a58eeec72?project=default&target=n2
    username: ""
  level: dbug
  message: Handling API request
timestamp: "2022-02-03T01:50:13.846415682+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: Got response struct from LXD
timestamp: "2022-02-03T01:50:14.105745856+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: "\n\t{\n\t\t\"id\": \"80c4b992-3cb1-4588-9fcc-b14a58eeec72\",\n\t\t\"class\":
    \"task\",\n\t\t\"description\": \"Creating instance\",\n\t\t\"created_at\": \"2022-02-03T01:50:12.880337898+01:00\",\n\t\t\"updated_at\":
    \"2022-02-03T01:50:12.880337898+01:00\",\n\t\t\"status\": \"Running\",\n\t\t\"status_code\":
    103,\n\t\t\"resources\": {\n\t\t\t\"containers\": [\n\t\t\t\t\"/1.0/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t],\n\t\t\t\"instances\":
    [\n\t\t\t\t\"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t]\n\t\t},\n\t\t\"metadata\":
    null,\n\t\t\"may_cancel\": false,\n\t\t\"err\": \"\",\n\t\t\"location\": \"n2\"\n\t}"
timestamp: "2022-02-03T01:50:14.106978601+01:00"
type: logging


location: n2
metadata:
  context:
    http_code: "200"
  level: dbug
  message: "WriteJSON\n\t{\n\t\t\"type\": \"sync\",\n\t\t\"status\": \"Success\",\n\t\t\"status_code\":
    200,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 0,\n\t\t\"error\": \"\",\n\t\t\"metadata\":
    {\n\t\t\t\"id\": \"80c4b992-3cb1-4588-9fcc-b14a58eeec72\",\n\t\t\t\"class\": \"task\",\n\t\t\t\"description\":
    \"Creating instance\",\n\t\t\t\"created_at\": \"2022-02-03T01:50:12.880337898+01:00\",\n\t\t\t\"updated_at\":
    \"2022-02-03T01:50:12.880337898+01: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/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\n\t\t\t\t],\n\t\t\t\t\"instances\":
    [\n\t\t\t\t\t\"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9\"\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\":
    \"n2\"\n\t\t}\n\t}"
timestamp: "2022-02-03T01:50:14.101235279+01:00"
type: logging


location: n1
metadata:
  context:
    address: 10.0.1.31:8443
  level: dbug
  message: Sending heartbeat request
timestamp: "2022-02-03T01:50:15.071620882+01:00"
type: logging


location: n2
metadata:
  context:
    raftMembers: '[{{1 10.0.1.30:8443 voter} n1} {{2 10.0.1.31:8443 stand-by} n2}]'
  level: dbug
  message: Replace current raft nodes
timestamp: "2022-02-03T01:50:15.27859838+01:00"
type: logging


location: n2
metadata:
  context:
    fingerprint: 02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf
    subject: CN=root@n1,O=linuxcontainers.org
  level: dbug
  message: Matched trusted cert
timestamp: "2022-02-03T01:50:15.278321526+01:00"
type: logging


location: n1
metadata:
  context:
    remote: 10.0.1.31:8443
  level: dbug
  message: Successful heartbeat
timestamp: "2022-02-03T01:50:15.295370338+01:00"
type: logging


location: n1
metadata:
  context:
    local: 10.0.1.30:8443
  level: dbug
  message: Rebalancing member roles in heartbeat
timestamp: "2022-02-03T01:50:15.304280009+01:00"
type: logging


location: n2
metadata:
  context: {}
  level: dbug
  message: 'Failure for task operation: 80c4b992-3cb1-4588-9fcc-b14a58eeec72: Error
    transferring instance data: websocket: bad handshake'
timestamp: "2022-02-03T01:50:15.435207907+01:00"
type: logging


location: n1
metadata:
  context:
    duration: 6.741652996s
    local: 10.0.1.30:8443
  level: dbug
  message: Completed heartbeat round
timestamp: "2022-02-03T01:50:15.476659791+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: 'Updated metadata for task Operation: 0d5ac0d2-fe94-47d2-a236-36583bf0fa67'
timestamp: "2022-02-03T01:50:15.591958196+01:00"
type: logging


location: n1
metadata:
  context:
    etag: ""
    method: DELETE
    url: https://10.0.1.30:8443/1.0/operations/23b1ec3f-d589-4099-b4bd-e2228cce50d1?project=default
  level: dbug
  message: Sending request to LXD
timestamp: "2022-02-03T01:50:15.593987829+01:00"
type: logging


location: n2
metadata:
  class: task
  created_at: "2022-02-03T01:50:12.880337898+01:00"
  description: Creating instance
  err: 'Error transferring instance data: websocket: bad handshake'
  id: 80c4b992-3cb1-4588-9fcc-b14a58eeec72
  location: n2
  may_cancel: false
  metadata: null
  resources:
    containers:
    - /1.0/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
    instances:
    - /1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9
  status: Failure
  status_code: 400
  updated_at: "2022-02-03T01:50:12.880337898+01:00"
project: default
timestamp: "2022-02-03T01:50:15.587332745+01:00"
type: operation


location: n1
metadata:
  class: task
  created_at: "2022-02-03T01:50:01.327001709+01:00"
  description: Migrating instance
  err: ""
  id: 0d5ac0d2-fe94-47d2-a236-36583bf0fa67
  location: n1
  may_cancel: false
  metadata: {}
  resources:
    containers:
    - /1.0/containers/test1
    instances:
    - /1.0/instances/test1
  status: Running
  status_code: 103
  updated_at: "2022-02-03T01:50:15.591053691+01:00"
project: default
timestamp: "2022-02-03T01:50:15.658393376+01:00"
type: operation


location: n1
metadata:
  context:
    fingerprint: 02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf
    subject: CN=root@n1,O=linuxcontainers.org
  level: dbug
  message: Matched trusted cert
timestamp: "2022-02-03T01:50:15.659784349+01:00"
type: logging


location: n1
metadata:
  context:
    ip: 10.0.1.30:34224
    method: DELETE
    protocol: cluster
    url: /1.0/operations/23b1ec3f-d589-4099-b4bd-e2228cce50d1?project=default
    username: ""
  level: dbug
  message: Handling API request
timestamp: "2022-02-03T01:50:15.659919107+01:00"
type: logging


location: n1
metadata:
  context:
    http_code: "400"
  level: dbug
  message: "Error Response\n\t{\n\t\t\"type\": \"error\",\n\t\t\"status\": \"\",\n\t\t\"status_code\":
    0,\n\t\t\"operation\": \"\",\n\t\t\"error_code\": 400,\n\t\t\"error\": \"Only
    running operations can be cancelled\",\n\t\t\"metadata\": null\n\t}"
timestamp: "2022-02-03T01:50:15.660086398+01:00"
type: logging


location: n1
metadata:
  context: {}
  level: dbug
  message: 'Failure for task operation: 0d5ac0d2-fe94-47d2-a236-36583bf0fa67: Copy
    instance operation failed: Failed instance creation: Error transferring instance
    data: websocket: bad handshake'
timestamp: "2022-02-03T01:50:15.66221049+01:00"
type: logging


location: n1
metadata:
  class: task
  created_at: "2022-02-03T01:50:01.327001709+01:00"
  description: Migrating instance
  err: 'Copy instance operation failed: Failed instance creation: Error transferring
    instance data: websocket: bad handshake'
  id: 0d5ac0d2-fe94-47d2-a236-36583bf0fa67
  location: n1
  may_cancel: false
  metadata: {}
  resources:
    containers:
    - /1.0/containers/test1
    instances:
    - /1.0/instances/test1
  status: Failure
  status_code: 400
  updated_at: "2022-02-03T01:50:15.591053691+01:00"
project: default
timestamp: "2022-02-03T01:50:15.663592694+01:00"
type: operation


location: n1
metadata:
  context:
    listener: 13742aa1-07e6-46de-a9e3-a4ddf84e59db
    local: /var/snap/lxd/common/lxd/unix.socket
    localOnly: "false"
    remote: '@'
  level: dbug
  message: Event listener server handler stopped
timestamp: "2022-02-03T01:50:15.666112323+01:00"
type: logging


location: n1
metadata:
  context:
    local: 10.0.1.30:8443
    mode: normal
  level: dbug
  message: Starting heartbeat round
timestamp: "2022-02-03T01:50:18.703562932+01:00"
type: logging


location: n1
metadata:
  context:
    members: '[{{1 10.0.1.30:8443 voter} n1} {{2 10.0.1.31:8443 stand-by} n2}]'
  level: dbug
  message: Heartbeat updating local raft members
timestamp: "2022-02-03T01:50:18.704361117+01:00"
type: logging

Feb 03 '22 01:02 kriszos

this bug was probably introduced in 4.20 relevant thread https://discuss.linuxcontainers.org/t/lxc-move-error-websocket-bad-handshake/12754

Feb 03 '22 01:02 kriszos

Going to give that one to @tomponline to investigate.

It may be related to the TCP user timeout and keepalive options we've got enabled and that showed up around the 4.20 release, though it's configured with a 30s timeout and here we're seeing failures within 3s to 14s after operation creation.

Feb 03 '22 01:02 stgraber

As the connection appears to not being established, I'd be tempted to think its the connection timeout triggering.

Can you show the output of sudo ss -tlpn | grep lxd and ip a on the source host please?

Feb 04 '22 14:02 tomponline

root@n1:~# ss -tlpn | grep lxd LISTEN 0 4096 10.0.1.30:8443 0.0.0.0:* users:(("lxd",pid=1216,fd=20))

root@n1:~# ip addr 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000 link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 inet 127.0.0.1/8 scope host lo valid_lft forever preferred_lft forever inet6 ::1/128 scope host valid_lft forever preferred_lft forever 2: enp5s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP group default qlen 1000 link/ether 00:16:3e:6a:e1:67 brd ff:ff:ff:ff:ff:ff inet 10.0.1.30/24 brd 10.0.1.255 scope global dynamic enp5s0 valid_lft 170570sec preferred_lft 170570sec inet6 2001:470:65ec:1001:216:3eff:fe6a:e167/64 scope global dynamic mngtmpaddr noprefixroute valid_lft 2591840sec preferred_lft 604640sec inet6 fe80::216:3eff:fe6a:e167/64 scope link valid_lft forever preferred_lft forever

Feb 04 '22 15:02 kriszos

The problem is here

t=2022-02-03T00:19:08+0100 lvl=dbug msg="Database error: Failed updating heartbeat time for member \"10.0.1.30:8443\": database is locked" 
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Retry failed db interaction (Failed updating heartbeat time for member \"10.0.1.30:8443\": database is locked)" 
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Database error: Failed updating heartbeat time for member \"10.0.1.30:8443\": database is locked" 
t=2022-02-03T00:19:08+0100 lvl=dbug msg="Retry failed db interaction (Failed updating heartbeat time for member \"10.0.1.30:8443\": database is locked)" 
t=2022-02-03T00:19:09+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443
t=2022-02-03T00:19:09+0100 lvl=dbug msg="Completed heartbeat round" duration=854.16949ms local=10.0.1.30:8443
t=2022-02-03T00:19:12+0100 lvl=dbug msg="Failure for websocket operation: cd1b2ae1-b4c5-4e19-a06c-74ddc95c716d: Timed out waiting for connections"

The source host gives up waiting for the destination to connect.

But importantly there is also cluster database errors in that same section, suggesting that is causing the delays in the destination accessing the database. The database locked error is likely the issue due to another query running that is blocking writes. At what latency level does this issue start?

Feb 04 '22 18:02 tomponline

Also do you still see the heartbeat errors with latency introduced when not trying to move the instance?

Feb 04 '22 18:02 tomponline

Issue starts at 12ms in my production cluster, but in test environment that these logs are from it starts at around 30ms. Heartbeat errors shows only while moving instance with latency. example log bellow one database leader with latency while idling t=2022-02-07T12:47:05+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.33:8443 t=2022-02-07T12:47:05+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.33:8443 t=2022-02-07T12:47:11+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443 t=2022-02-07T12:47:11+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443 t=2022-02-07T12:47:11+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443 t=2022-02-07T12:47:11+0100 lvl=dbug msg="Completed heartbeat round" duration=7.019936987s local=10.0.1.30:8443 t=2022-02-07T12:47:14+0100 lvl=dbug msg="Starting heartbeat round" local=10.0.1.30:8443 mode=normal t=2022-02-07T12:47:14+0100 lvl=dbug msg="Heartbeat updating local raft members" members="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:voter} Name:n2} {NodeInfo:{ID:3 Address:10.0.1.33:8443 Role:voter} Name:n3}]" t=2022-02-07T12:47:15+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.33:8443 t=2022-02-07T12:47:15+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.33:8443 t=2022-02-07T12:47:17+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443 t=2022-02-07T12:47:17+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443 t=2022-02-07T12:47:17+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443 t=2022-02-07T12:47:17+0100 lvl=dbug msg="Completed heartbeat round" duration=2.899916512s local=10.0.1.30:8443 t=2022-02-07T12:47:24+0100 lvl=dbug msg="Starting heartbeat round" local=10.0.1.30:8443 mode=normal t=2022-02-07T12:47:24+0100 lvl=dbug msg="Heartbeat updating local raft members" members="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:voter} Name:n2} {NodeInfo:{ID:3 Address:10.0.1.33:8443 Role:voter} Name:n3}]" t=2022-02-07T12:47:25+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443 t=2022-02-07T12:47:25+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443 t=2022-02-07T12:47:25+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.33:8443 t=2022-02-07T12:47:25+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.33:8443 t=2022-02-07T12:47:26+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443 t=2022-02-07T12:47:26+0100 lvl=dbug msg="Completed heartbeat round" duration=1.481822967s local=10.0.1.30:8443 t=2022-02-07T12:47:34+0100 lvl=dbug msg="Starting heartbeat round" local=10.0.1.30:8443 mode=normal t=2022-02-07T12:47:34+0100 lvl=dbug msg="Heartbeat updating local raft members" members="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:voter} Name:n2} {NodeInfo:{ID:3 Address:10.0.1.33:8443 Role:voter} Name:n3}]" t=2022-02-07T12:47:37+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.33:8443 t=2022-02-07T12:47:37+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.33:8443 t=2022-02-07T12:47:39+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443 t=2022-02-07T12:47:39+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443 t=2022-02-07T12:47:39+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443 t=2022-02-07T12:47:39+0100 lvl=dbug msg="Completed heartbeat round" duration=4.905393039s local=10.0.1.30:8443 t=2022-02-07T12:47:44+0100 lvl=dbug msg="Starting heartbeat round" local=10.0.1.30:8443 mode=normal t=2022-02-07T12:47:44+0100 lvl=dbug msg="Heartbeat updating local raft members" members="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:voter} Name:n2} {NodeInfo:{ID:3 Address:10.0.1.33:8443 Role:voter} Name:n3}]" t=2022-02-07T12:47:45+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.33:8443 t=2022-02-07T12:47:45+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.33:8443 t=2022-02-07T12:47:50+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443 t=2022-02-07T12:47:50+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443 t=2022-02-07T12:47:51+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443 t=2022-02-07T12:47:51+0100 lvl=dbug msg="Completed heartbeat round" duration=6.410853622s local=10.0.1.30:8443 t=2022-02-07T12:47:54+0100 lvl=dbug msg="Starting heartbeat round" local=10.0.1.30:8443 mode=normal t=2022-02-07T12:47:54+0100 lvl=dbug msg="Heartbeat updating local raft members" members="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:voter} Name:n2} {NodeInfo:{ID:3 Address:10.0.1.33:8443 Role:voter} Name:n3}]"

Thou while there is no additional delay there are errors while moving instance: t=2022-02-07T12:25:23+0100 lvl=dbug msg="Database error: &fmt.wrapError{msg:"Delete \"operations\": database is locked", err:protocol.Error{Code:5, Message:"database is locked"}}" t=2022-02-07T12:25:23+0100 lvl=dbug msg="Retry failed db interaction (Delete "operations": database is locked)"

full log while moving without latency bellow:

t=2022-02-07T12:25:09+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443 t=2022-02-07T12:25:10+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443 t=2022-02-07T12:25:10+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443 t=2022-02-07T12:25:10+0100 lvl=dbug msg="Completed heartbeat round" duration=5.363513991s local=10.0.1.30:8443 t=2022-02-07T12:25:14+0100 lvl=dbug msg="Starting heartbeat round" local=10.0.1.30:8443 mode=normal t=2022-02-07T12:25:14+0100 lvl=dbug msg="Heartbeat updating local raft members" members="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:voter} Name:n2} {NodeInfo:{ID:3 Address:10.0.1.33:8443 Role:voter} Name:n3}]" t=2022-02-07T12:25:14+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443 t=2022-02-07T12:25:14+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443 t=2022-02-07T12:25:16+0100 lvl=dbug msg="Handling API request" ip=@ method=GET protocol=unix url=/1.0 username=root t=2022-02-07T12:25:16+0100 lvl=dbug msg="WriteJSON\n\t{\n\t\t"type": "sync",\n\t\t"status": "Success",\n\t\t"status_code": 200,\n\t\t"operation": "",\n\t\t"error_code": 0,\n\t\t"error": "",\n\t\t"metadata": {\n\t\t\t"config": {\n\t\t\t\t"cluster.https_address": "10.0.1.30:8443",\n\t\t\t\t"core.https_address": "10.0.1.30:8443",\n\t\t\t\t"core.trust_password": true\n\t\t\t},\n\t\t\t"api_extensions": [\n\t\t\t\t"storage_zfs_remove_snapshots",\n\t\t\t\t"container_host_shutdown_timeout",\n\t\t\t\t"container_stop_priority",\n\t\t\t\t"container_syscall_filtering",\n\t\t\t\t"auth_pki",\n\t\t\t\t"container_last_used_at",\n\t\t\t\t"etag",\n\t\t\t\t"patch",\n\t\t\t\t"usb_devices",\n\t\t\t\t"https_allowed_credentials",\n\t\t\t\t"image_compression_algorithm",\n\t\t\t\t"directory_manipulation",\n\t\t\t\t"container_cpu_time",\n\t\t\t\t"storage_zfs_use_refquota",\n\t\t\t\t"storage_lvm_mount_options",\n\t\t\t\t"network",\n\t\t\t\t"profile_usedby",\n\t\t\t\t"container_push",\n\t\t\t\t"container_exec_recording",\n\t\t\t\t"certificate_update",\n\t\t\t\t"container_exec_signal_handling",\n\t\t\t\t"gpu_devices",\n\t\t\t\t"container_image_properties",\n\t\t\t\t"migration_progress",\n\t\t\t\t"id_map",\n\t\t\t\t"network_firewall_filtering",\n\t\t\t\t"network_routes",\n\t\t\t\t"storage",\n\t\t\t\t"file_delete",\n\t\t\t\t"file_append",\n\t\t\t\t"network_dhcp_expiry",\n\t\t\t\t"storage_lvm_vg_rename",\n\t\t\t\t"storage_lvm_thinpool_rename",\n\t\t\t\t"network_vlan",\n\t\t\t\t"image_create_aliases",\n\t\t\t\t"container_stateless_copy",\n\t\t\t\t"container_only_migration",\n\t\t\t\t"storage_zfs_clone_copy",\n\t\t\t\t"unix_device_rename",\n\t\t\t\t"storage_lvm_use_thinpool",\n\t\t\t\t"storage_rsync_bwlimit",\n\t\t\t\t"network_vxlan_interface",\n\t\t\t\t"storage_btrfs_mount_options",\n\t\t\t\t"entity_description",\n\t\t\t\t"image_force_refresh",\n\t\t\t\t"storage_lvm_lv_resizing",\n\t\t\t\t"id_map_base",\n\t\t\t\t"file_symlinks",\n\t\t\t\t"container_push_target",\n\t\t\t\t"network_vlan_physical",\n\t\t\t\t"storage_images_delete",\n\t\t\t\t"container_edit_metadata",\n\t\t\t\t"container_snapshot_stateful_migration",\n\t\t\t\t"storage_driver_ceph",\n\t\t\t\t"storage_ceph_user_name",\n\t\t\t\t"resource_limits",\n\t\t\t\t"storage_volatile_initial_source",\n\t\t\t\t"storage_ceph_force_osd_reuse",\n\t\t\t\t"storage_block_filesystem_btrfs",\n\t\t\t\t"resources",\n\t\t\t\t"kernel_limits",\n\t\t\t\t"storage_api_volume_rename",\n\t\t\t\t"macaroon_authentication",\n\t\t\t\t"network_sriov",\n\t\t\t\t"console",\n\t\t\t\t"restrict_devlxd",\n\t\t\t\t"migration_pre_copy",\n\t\t\t\t"infiniband",\n\t\t\t\t"maas_network",\n\t\t\t\t"devlxd_events",\n\t\t\t\t"proxy",\n\t\t\t\t"network_dhcp_gateway",\n\t\t\t\t"file_get_symlink",\n\t\t\t\t"network_leases",\n\t\t\t\t"unix_device_hotplug",\n\t\t\t\t"storage_api_local_volume_handling",\n\t\t\t\t"operation_description",\n\t\t\t\t"clustering",\n\t\t\t\t"event_lifecycle",\n\t\t\t\t"storage_api_remote_volume_handling",\n\t\t\t\t"nvidia_runtime",\n\t\t\t\t"container_mount_propagation",\n\t\t\t\t"container_backup",\n\t\t\t\t"devlxd_images",\n\t\t\t\t"container_local_cross_pool_handling",\n\t\t\t\t"proxy_unix",\n\t\t\t\t"proxy_udp",\n\t\t\t\t"clustering_join",\n\t\t\t\t"proxy_tcp_udp_multi_port_handling",\n\t\t\t\t"network_state",\n\t\t\t\t"proxy_unix_dac_properties",\n\t\t\t\t"container_protection_delete",\n\t\t\t\t"unix_priv_drop",\n\t\t\t\t"pprof_http",\n\t\t\t\t"proxy_haproxy_protocol",\n\t\t\t\t"network_hwaddr",\n\t\t\t\t"proxy_nat",\n\t\t\t\t"network_nat_order",\n\t\t\t\t"container_full",\n\t\t\t\t"candid_authentication",\n\t\t\t\t"backup_compression",\n\t\t\t\t"candid_config",\n\t\t\t\t"nvidia_runtime_config",\n\t\t\t\t"storage_api_volume_snapshots",\n\t\t\t\t"storage_unmapped",\n\t\t\t\t"projects",\n\t\t\t\t"candid_config_key",\n\t\t\t\t"network_vxlan_ttl",\n\t\t\t\t"container_incremental_copy",\n\t\t\t\t"usb_optional_vendorid",\n\t\t\t\t"snapshot_scheduling",\n\t\t\t\t"snapshot_schedule_aliases",\n\t\t\t\t"container_copy_project",\n\t\t\t\t"clustering_server_address",\n\t\t\t\t"clustering_image_replication",\n\t\t\t\t"container_protection_shift",\n\t\t\t\t"snapshot_expiry",\n\t\t\t\t"container_backup_override_pool",\n\t\t\t\t"snapshot_expiry_creation",\n\t\t\t\t"network_leases_location",\n\t\t\t\t"resources_cpu_socket",\n\t\t\t\t"resources_gpu",\n\t\t\t\t"resources_numa",\n\t\t\t\t"kernel_features",\n\t\t\t\t"id_map_current",\n\t\t\t\t"event_location",\n\t\t\t\t"storage_api_remote_volume_snapshots",\n\t\t\t\t"network_nat_address",\n\t\t\t\t"container_nic_routes",\n\t\t\t\t"rbac",\n\t\t\t\t"cluster_internal_copy",\n\t\t\t\t"seccomp_notify",\n\t\t\t\t"lxc_features",\n\t\t\t\t"container_nic_ipvlan",\n\t\t\t\t"network_vlan_sriov",\n\t\t\t\t"storage_cephfs",\n\t\t\t\t"container_nic_ipfilter",\n\t\t\t\t"resources_v2",\n\t\t\t\t"container_exec_user_group_cwd",\n\t\t\t\t"container_syscall_intercept",\n\t\t\t\t"container_disk_shift",\n\t\t\t\t"storage_shifted",\n\t\t\t\t"resources_infiniband",\n\t\t\t\t"daemon_storage",\n\t\t\t\t"instances",\n\t\t\t\t"image_types",\n\t\t\t\t"resources_disk_sata",\n\t\t\t\t"clustering_roles",\n\t\t\t\t"images_expiry",\n\t\t\t\t"resources_network_firmware",\n\t\t\t\t"backup_compression_algorithm",\n\t\t\t\t"ceph_data_pool_name",\n\t\t\t\t"container_syscall_intercept_mount",\n\t\t\t\t"compression_squashfs",\n\t\t\t\t"container_raw_mount",\n\t\t\t\t"container_nic_routed",\n\t\t\t\t"container_syscall_intercept_mount_fuse",\n\t\t\t\t"container_disk_ceph",\n\t\t\t\t"virtual-machines",\n\t\t\t\t"image_profiles",\n\t\t\t\t"clustering_architecture",\n\t\t\t\t"resources_disk_id",\n\t\t\t\t"storage_lvm_stripes",\n\t\t\t\t"vm_boot_priority",\n\t\t\t\t"unix_hotplug_devices",\n\t\t\t\t"api_filtering",\n\t\t\t\t"instance_nic_network",\n\t\t\t\t"clustering_sizing",\n\t\t\t\t"firewall_driver",\n\t\t\t\t"projects_limits",\n\t\t\t\t"container_syscall_intercept_hugetlbfs",\n\t\t\t\t"limits_hugepages",\n\t\t\t\t"container_nic_routed_gateway",\n\t\t\t\t"projects_restrictions",\n\t\t\t\t"custom_volume_snapshot_expiry",\n\t\t\t\t"volume_snapshot_scheduling",\n\t\t\t\t"trust_ca_certificates",\n\t\t\t\t"snapshot_disk_usage",\n\t\t\t\t"clustering_edit_roles",\n\t\t\t\t"container_nic_routed_host_address",\n\t\t\t\t"container_nic_ipvlan_gateway",\n\t\t\t\t"resources_usb_pci",\n\t\t\t\t"resources_cpu_threads_numa",\n\t\t\t\t"resources_cpu_core_die",\n\t\t\t\t"api_os",\n\t\t\t\t"container_nic_routed_host_table",\n\t\t\t\t"container_nic_ipvlan_host_table",\n\t\t\t\t"container_nic_ipvlan_mode",\n\t\t\t\t"resources_system",\n\t\t\t\t"images_push_relay",\n\t\t\t\t"network_dns_search",\n\t\t\t\t"container_nic_routed_limits",\n\t\t\t\t"instance_nic_bridged_vlan",\n\t\t\t\t"network_state_bond_bridge",\n\t\t\t\t"usedby_consistency",\n\t\t\t\t"custom_block_volumes",\n\t\t\t\t"clustering_failure_domains",\n\t\t\t\t"resources_gpu_mdev",\n\t\t\t\t"console_vga_type",\n\t\t\t\t"projects_limits_disk",\n\t\t\t\t"network_type_macvlan",\n\t\t\t\t"network_type_sriov",\n\t\t\t\t"container_syscall_intercept_bpf_devices",\n\t\t\t\t"network_type_ovn",\n\t\t\t\t"projects_networks",\n\t\t\t\t"projects_networks_restricted_uplinks",\n\t\t\t\t"custom_volume_backup",\n\t\t\t\t"backup_override_name",\n\t\t\t\t"storage_rsync_compression",\n\t\t\t\t"network_type_physical",\n\t\t\t\t"network_ovn_external_subnets",\n\t\t\t\t"network_ovn_nat",\n\t\t\t\t"network_ovn_external_routes_remove",\n\t\t\t\t"tpm_device_type",\n\t\t\t\t"storage_zfs_clone_copy_rebase",\n\t\t\t\t"gpu_mdev",\n\t\t\t\t"resources_pci_iommu",\n\t\t\t\t"resources_network_usb",\n\t\t\t\t"resources_disk_address",\n\t\t\t\t"network_physical_ovn_ingress_mode",\n\t\t\t\t"network_ovn_dhcp",\n\t\t\t\t"network_physical_routes_anycast",\n\t\t\t\t"projects_limits_instances",\n\t\t\t\t"network_state_vlan",\n\t\t\t\t"instance_nic_bridged_port_isolation",\n\t\t\t\t"instance_bulk_state_change",\n\t\t\t\t"network_gvrp",\n\t\t\t\t"instance_pool_move",\n\t\t\t\t"gpu_sriov",\n\t\t\t\t"pci_device_type",\n\t\t\t\t"storage_volume_state",\n\t\t\t\t"network_acl",\n\t\t\t\t"migration_stateful",\n\t\t\t\t"disk_state_quota",\n\t\t\t\t"storage_ceph_features",\n\t\t\t\t"projects_compression",\n\t\t\t\t"projects_images_remote_cache_expiry",\n\t\t\t\t"certificate_project",\n\t\t\t\t"network_ovn_acl",\n\t\t\t\t"projects_images_auto_update",\n\t\t\t\t"projects_restricted_cluster_target",\n\t\t\t\t"images_default_architecture",\n\t\t\t\t"network_ovn_acl_defaults",\n\t\t\t\t"gpu_mig",\n\t\t\t\t"project_usage",\n\t\t\t\t"network_bridge_acl",\n\t\t\t\t"warnings",\n\t\t\t\t"projects_restricted_backups_and_snapshots",\n\t\t\t\t"clustering_join_token",\n\t\t\t\t"clustering_description",\n\t\t\t\t"server_trusted_proxy",\n\t\t\t\t"clustering_update_cert",\n\t\t\t\t"storage_api_project",\n\t\t\t\t"server_instance_driver_operational",\n\t\t\t\t"server_supported_storage_drivers",\n\t\t\t\t"event_lifecycle_requestor_address",\n\t\t\t\t"resources_gpu_usb",\n\t\t\t\t"clustering_evacuation",\n\t\t\t\t"network_ovn_nat_address",\n\t\t\t\t"network_bgp",\n\t\t\t\t"network_forward",\n\t\t\t\t"custom_volume_refresh",\n\t\t\t\t"network_counters_errors_dropped",\n\t\t\t\t"metrics",\n\t\t\t\t"image_source_project",\n\t\t\t\t"clustering_config",\n\t\t\t\t"network_peer",\n\t\t\t\t"linux_sysctl",\n\t\t\t\t"network_dns",\n\t\t\t\t"ovn_nic_acceleration",\n\t\t\t\t"certificate_self_renewal",\n\t\t\t\t"instance_project_move",\n\t\t\t\t"storage_volume_project_move",\n\t\t\t\t"cloud_init",\n\t\t\t\t"network_dns_nat",\n\t\t\t\t"database_leader",\n\t\t\t\t"instance_all_projects",\n\t\t\t\t"clustering_groups",\n\t\t\t\t"ceph_rbd_du",\n\t\t\t\t"instance_get_full",\n\t\t\t\t"qemu_metrics",\n\t\t\t\t"gpu_mig_uuid",\n\t\t\t\t"event_project",\n\t\t\t\t"clustering_evacuation_live",\n\t\t\t\t"instance_allow_inconsistent_copy"\n\t\t\t],\n\t\t\t"api_status": "stable",\n\t\t\t"api_version": "1.0",\n\t\t\t"auth": "trusted",\n\t\t\t"public": false,\n\t\t\t"auth_methods": [\n\t\t\t\t"tls"\n\t\t\t],\n\t\t\t"environment": {\n\t\t\t\t"addresses": [\n\t\t\t\t\t"10.0.1.30:8443"\n\t\t\t\t],\n\t\t\t\t"architectures": [\n\t\t\t\t\t"x86_64",\n\t\t\t\t\t"i686"\n\t\t\t\t],\n\t\t\t\t"certificate": "-----BEGIN CERTIFICATE-----\nMIIB9zCCAX2gAwIBAgIQAKR8eYGnbF+EvD3i0Q2/czAKBggqhkjOPQQDAzAwMRww\nGgYDVQQKExNsaW51eGNvbnRhaW5lcnMub3JnMRAwDgYDVQQDDAdyb290QG4xMB4X\nDTIyMDIwMjE4NTEwNloXDTMyMDEzMTE4NTEwNlowMDEcMBoGA1UEChMTbGludXhj\nb250YWluZXJzLm9yZzEQMA4GA1UEAwwHcm9vdEBuMTB2MBAGByqGSM49AgEGBSuB\nBAAiA2IABJ92bn9+Zafi3DNlQ1C21Zew9oKMRCZTQUHA2G9U7ZTVqli76qOGUc4n\nfAcasrnXOGkPP4AmbQYeoZSewuRHi2Tv0sjQBnrKOr1gnNXvFBnKcFYptyRTIf3n\nCj6d1YF57qNcMFowDgYDVR0PAQH/BAQDAgWgMBMGA1UdJQQMMAoGCCsGAQUFBwMB\nMAwGA1UdEwEB/wQCMAAwJQYDVR0RBB4wHIICbjGHBH8AAAGHEAAAAAAAAAAAAAAA\nAAAAAAEwCgYIKoZIzj0EAwMDaAAwZQIxAMFPCl+cVhLJ/wEt+t9VE3dbcIs/qtFV\nlO3y/FeYBqju1Z1pcW80K/4lL+NU+1ZdiAIwAc6pef1thBUpauxvLUfdikMQbIgX\n2B07zaER8uITxdN7iWtAz9mmtpqF4H1Yf9HX\n-----END CERTIFICATE-----\n",\n\t\t\t\t"certificate_fingerprint": "c1b8cf714ff7381fafa0ebc36f7eeb544b5d2dc14e8cdf35c2cfd762d9ba7e5d",\n\t\t\t\t"driver": "lxc",\n\t\t\t\t"driver_version": "4.0.12",\n\t\t\t\t"firewall": "nftables",\n\t\t\t\t"kernel": "Linux",\n\t\t\t\t"kernel_architecture": "x86_64",\n\t\t\t\t"kernel_features": {\n\t\t\t\t\t"netnsid_getifaddrs": "true",\n\t\t\t\t\t"seccomp_listener": "true",\n\t\t\t\t\t"seccomp_listener_continue": "true",\n\t\t\t\t\t"shiftfs": "false",\n\t\t\t\t\t"uevent_injection": "true",\n\t\t\t\t\t"unpriv_fscaps": "true"\n\t\t\t\t},\n\t\t\t\t"kernel_version": "5.4.0-97-generic",\n\t\t\t\t"lxc_features": {\n\t\t\t\t\t"cgroup2": "true",\n\t\t\t\t\t"core_scheduling": "true",\n\t\t\t\t\t"devpts_fd": "true",\n\t\t\t\t\t"idmapped_mounts_v2": "true",\n\t\t\t\t\t"mount_injection_file": "true",\n\t\t\t\t\t"network_gateway_device_route": "true",\n\t\t\t\t\t"network_ipvlan": "true",\n\t\t\t\t\t"network_l2proxy": "true",\n\t\t\t\t\t"network_phys_macvlan_mtu": "true",\n\t\t\t\t\t"network_veth_router": "true",\n\t\t\t\t\t"pidfd": "true",\n\t\t\t\t\t"seccomp_allow_deny_syntax": "true",\n\t\t\t\t\t"seccomp_notify": "true",\n\t\t\t\t\t"seccomp_proxy_send_notify_fd": "true"\n\t\t\t\t},\n\t\t\t\t"os_name": "Ubuntu",\n\t\t\t\t"os_version": "20.04",\n\t\t\t\t"project": "default",\n\t\t\t\t"server": "lxd",\n\t\t\t\t"server_clustered": true,\n\t\t\t\t"server_name": "n1",\n\t\t\t\t"server_pid": 1210,\n\t\t\t\t"server_version": "4.22",\n\t\t\t\t"storage": "zfs",\n\t\t\t\t"storage_version": "0.8.3-1ubuntu12.13",\n\t\t\t\t"storage_supported_drivers": [\n\t\t\t\t\t{\n\t\t\t\t\t\t"Name": "btrfs",\n\t\t\t\t\t\t"Version": "5.4.1",\n\t\t\t\t\t\t"Remote": false\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t"Name": "cephfs",\n\t\t\t\t\t\t"Version": "15.2.14",\n\t\t\t\t\t\t"Remote": true\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t"Name": "dir",\n\t\t\t\t\t\t"Version": "1",\n\t\t\t\t\t\t"Remote": false\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t"Name": "lvm",\n\t\t\t\t\t\t"Version": "2.03.07(2) (2019-11-30) / 1.02.167 (2019-11-30) / 4.41.0",\n\t\t\t\t\t\t"Remote": false\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t"Name": "zfs",\n\t\t\t\t\t\t"Version": "0.8.3-1ubuntu12.13",\n\t\t\t\t\t\t"Remote": false\n\t\t\t\t\t},\n\t\t\t\t\t{\n\t\t\t\t\t\t"Name": "ceph",\n\t\t\t\t\t\t"Version": "15.2.14",\n\t\t\t\t\t\t"Remote": true\n\t\t\t\t\t}\n\t\t\t\t]\n\t\t\t}\n\t\t}\n\t}" http_code=200 t=2022-02-07T12:25:16+0100 lvl=dbug msg="Handling API request" ip=@ method=GET protocol=unix url="/1.0/events?target=n2" username=root t=2022-02-07T12:25:16+0100 lvl=dbug msg="Event listener server handler started" listener=74ded8f9-25d6-41d0-87ff-39ac10677f31 local=/var/snap/lxd/common/lxd/unix.socket localOnly=false remote=@ t=2022-02-07T12:25:16+0100 lvl=dbug msg="Handling API request" ip=@ method=POST protocol=unix url="/1.0/instances/test1?target=n2" username=root t=2022-02-07T12:25:16+0100 lvl=dbug msg="New task Operation: 5eef458d-ee01-456d-abf2-2387b0752ea5" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Started task operation: 5eef458d-ee01-456d-abf2-2387b0752ea5" t=2022-02-07T12:25:16+0100 lvl=dbug msg="WriteJSON\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/5eef458d-ee01-456d-abf2-2387b0752ea5",\n\t\t"error_code": 0,\n\t\t"error": "",\n\t\t"metadata": {\n\t\t\t"id": "5eef458d-ee01-456d-abf2-2387b0752ea5",\n\t\t\t"class": "task",\n\t\t\t"description": "Migrating instance",\n\t\t\t"created_at": "2022-02-07T12:25:16.558486726+01:00",\n\t\t\t"updated_at": "2022-02-07T12:25:16.558486726+01: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/containers/test1"\n\t\t\t\t],\n\t\t\t\t"instances": [\n\t\t\t\t\t"/1.0/instances/test1"\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": "n1"\n\t\t}\n\t}" http_code=202 t=2022-02-07T12:25:16+0100 lvl=dbug msg="Handling API request" ip=@ method=GET protocol=unix url="/1.0/operations/5eef458d-ee01-456d-abf2-2387b0752ea5?target=n2" username=root t=2022-02-07T12:25:16+0100 lvl=dbug msg="WriteJSON\n\t{\n\t\t"type": "sync",\n\t\t"status": "Success",\n\t\t"status_code": 200,\n\t\t"operation": "",\n\t\t"error_code": 0,\n\t\t"error": "",\n\t\t"metadata": {\n\t\t\t"id": "5eef458d-ee01-456d-abf2-2387b0752ea5",\n\t\t\t"class": "task",\n\t\t\t"description": "Migrating instance",\n\t\t\t"created_at": "2022-02-07T12:25:16.558486726+01:00",\n\t\t\t"updated_at": "2022-02-07T12:25:16.558486726+01: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/containers/test1"\n\t\t\t\t],\n\t\t\t\t"instances": [\n\t\t\t\t\t"/1.0/instances/test1"\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": "n1"\n\t\t}\n\t}" http_code=200 t=2022-02-07T12:25:16+0100 lvl=dbug msg="Connecting to a remote LXD over HTTPS" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Connecting to a remote LXD over HTTPS" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Sending request to LXD" etag= method=GET url="https://10.0.1.30:8443/1.0/instances/test1?project=default" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:34524 method=GET protocol=cluster url="/1.0/instances/test1?project=default" username= t=2022-02-07T12:25:16+0100 lvl=dbug msg="WriteJSON\n\t{\n\t\t"type": "sync",\n\t\t"status": "Success",\n\t\t"status_code": 200,\n\t\t"operation": "",\n\t\t"error_code": 0,\n\t\t"error": "",\n\t\t"metadata": {\n\t\t\t"architecture": "x86_64",\n\t\t\t"config": {\n\t\t\t\t"image.architecture": "amd64",\n\t\t\t\t"image.description": "Alpine edge amd64 (20220201_13:00)",\n\t\t\t\t"image.os": "Alpine",\n\t\t\t\t"image.release": "edge",\n\t\t\t\t"image.serial": "20220201_13:00",\n\t\t\t\t"image.type": "squashfs",\n\t\t\t\t"image.variant": "default",\n\t\t\t\t"volatile.base_image": "859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee",\n\t\t\t\t"volatile.eth0.hwaddr": "00:16:3e:2f:90:a7",\n\t\t\t\t"volatile.idmap.base": "0",\n\t\t\t\t"volatile.idmap.current": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t\t"volatile.idmap.next": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t\t"volatile.last_state.idmap": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t\t"volatile.last_state.power": "STOPPED",\n\t\t\t\t"volatile.uuid": "3c09669f-77ac-4060-8231-4461906378a9"\n\t\t\t},\n\t\t\t"devices": {},\n\t\t\t"ephemeral": false,\n\t\t\t"profiles": [\n\t\t\t\t"default"\n\t\t\t],\n\t\t\t"stateful": false,\n\t\t\t"description": "",\n\t\t\t"created_at": "2022-02-07T11:24:03.728895366Z",\n\t\t\t"expanded_config": {\n\t\t\t\t"image.architecture": "amd64",\n\t\t\t\t"image.description": "Alpine edge amd64 (20220201_13:00)",\n\t\t\t\t"image.os": "Alpine",\n\t\t\t\t"image.release": "edge",\n\t\t\t\t"image.serial": "20220201_13:00",\n\t\t\t\t"image.type": "squashfs",\n\t\t\t\t"image.variant": "default",\n\t\t\t\t"volatile.base_image": "859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee",\n\t\t\t\t"volatile.eth0.hwaddr": "00:16:3e:2f:90:a7",\n\t\t\t\t"volatile.idmap.base": "0",\n\t\t\t\t"volatile.idmap.current": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t\t"volatile.idmap.next": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t\t"volatile.last_state.idmap": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t\t"volatile.last_state.power": "STOPPED",\n\t\t\t\t"volatile.uuid": "3c09669f-77ac-4060-8231-4461906378a9"\n\t\t\t},\n\t\t\t"expanded_devices": {\n\t\t\t\t"eth0": {\n\t\t\t\t\t"name": "eth0",\n\t\t\t\t\t"nictype": "macvlan",\n\t\t\t\t\t"parent": "enp5s0",\n\t\t\t\t\t"type": "nic"\n\t\t\t\t},\n\t\t\t\t"root": {\n\t\t\t\t\t"path": "/",\n\t\t\t\t\t"pool": "local",\n\t\t\t\t\t"type": "disk"\n\t\t\t\t}\n\t\t\t},\n\t\t\t"name": "test1",\n\t\t\t"status": "Stopped",\n\t\t\t"status_code": 102,\n\t\t\t"last_used_at": "1970-01-01T00:00:00Z",\n\t\t\t"location": "n1",\n\t\t\t"type": "container",\n\t\t\t"project": "default"\n\t\t}\n\t}" http_code=200 t=2022-02-07T12:25:16+0100 lvl=dbug msg="Got response struct from LXD" t=2022-02-07T12:25:16+0100 lvl=dbug msg="\n\t{\n\t\t"architecture": "x86_64",\n\t\t"config": {\n\t\t\t"image.architecture": "amd64",\n\t\t\t"image.description": "Alpine edge amd64 (20220201_13:00)",\n\t\t\t"image.os": "Alpine",\n\t\t\t"image.release": "edge",\n\t\t\t"image.serial": "20220201_13:00",\n\t\t\t"image.type": "squashfs",\n\t\t\t"image.variant": "default",\n\t\t\t"volatile.base_image": "859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee",\n\t\t\t"volatile.eth0.hwaddr": "00:16:3e:2f:90:a7",\n\t\t\t"volatile.idmap.base": "0",\n\t\t\t"volatile.idmap.current": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t"volatile.idmap.next": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t"volatile.last_state.idmap": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t"volatile.last_state.power": "STOPPED",\n\t\t\t"volatile.uuid": "3c09669f-77ac-4060-8231-4461906378a9"\n\t\t},\n\t\t"devices": {},\n\t\t"ephemeral": false,\n\t\t"profiles": [\n\t\t\t"default"\n\t\t],\n\t\t"stateful": false,\n\t\t"description": "",\n\t\t"created_at": "2022-02-07T11:24:03.728895366Z",\n\t\t"expanded_config": {\n\t\t\t"image.architecture": "amd64",\n\t\t\t"image.description": "Alpine edge amd64 (20220201_13:00)",\n\t\t\t"image.os": "Alpine",\n\t\t\t"image.release": "edge",\n\t\t\t"image.serial": "20220201_13:00",\n\t\t\t"image.type": "squashfs",\n\t\t\t"image.variant": "default",\n\t\t\t"volatile.base_image": "859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee",\n\t\t\t"volatile.eth0.hwaddr": "00:16:3e:2f:90:a7",\n\t\t\t"volatile.idmap.base": "0",\n\t\t\t"volatile.idmap.current": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t"volatile.idmap.next": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t"volatile.last_state.idmap": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t"volatile.last_state.power": "STOPPED",\n\t\t\t"volatile.uuid": "3c09669f-77ac-4060-8231-4461906378a9"\n\t\t},\n\t\t"expanded_devices": {\n\t\t\t"eth0": {\n\t\t\t\t"name": "eth0",\n\t\t\t\t"nictype": "macvlan",\n\t\t\t\t"parent": "enp5s0",\n\t\t\t\t"type": "nic"\n\t\t\t},\n\t\t\t"root": {\n\t\t\t\t"path": "/",\n\t\t\t\t"pool": "local",\n\t\t\t\t"type": "disk"\n\t\t\t}\n\t\t},\n\t\t"name": "test1",\n\t\t"status": "Stopped",\n\t\t"status_code": 102,\n\t\t"last_used_at": "1970-01-01T00:00:00Z",\n\t\t"location": "n1",\n\t\t"type": "container",\n\t\t"project": "default"\n\t}" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:34526 method=GET protocol=cluster url="/1.0/events?project=default" username= t=2022-02-07T12:25:16+0100 lvl=dbug msg="Connected to the websocket: wss://10.0.1.30:8443/1.0/events?project=default" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Sending request to LXD" etag= method=POST url="https://10.0.1.30:8443/1.0/instances/test1?project=default" t=2022-02-07T12:25:16+0100 lvl=dbug msg="\n\t{\n\t\t"name": "",\n\t\t"migration": true,\n\t\t"live": false,\n\t\t"instance_only": false,\n\t\t"container_only": false,\n\t\t"target": null,\n\t\t"pool": "",\n\t\t"project": ""\n\t}" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Event listener server handler started" listener=6c16189f-0abe-48f8-9a42-0097977120dd local=10.0.1.30:8443 localOnly=true remote=10.0.1.30:34526 t=2022-02-07T12:25:16+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:34528 method=POST protocol=cluster url="/1.0/instances/test1?project=default" username= t=2022-02-07T12:25:16+0100 lvl=dbug msg="New websocket Operation: 40a69811-161f-4702-8524-7d3839a2d183" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Started websocket operation: 40a69811-161f-4702-8524-7d3839a2d183" t=2022-02-07T12:25:16+0100 lvl=info msg="Waiting for migration channel connections" t=2022-02-07T12:25:16+0100 lvl=dbug msg="WriteJSON\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/40a69811-161f-4702-8524-7d3839a2d183",\n\t\t"error_code": 0,\n\t\t"error": "",\n\t\t"metadata": {\n\t\t\t"id": "40a69811-161f-4702-8524-7d3839a2d183",\n\t\t\t"class": "websocket",\n\t\t\t"description": "Migrating instance",\n\t\t\t"created_at": "2022-02-07T12:25:16.716237873+01:00",\n\t\t\t"updated_at": "2022-02-07T12:25:16.716237873+01: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/containers/test1"\n\t\t\t\t],\n\t\t\t\t"instances": [\n\t\t\t\t\t"/1.0/instances/test1"\n\t\t\t\t]\n\t\t\t},\n\t\t\t"metadata": {\n\t\t\t\t"control": "83a8754d01d70515f4e1af892c91676b897d257a7626bae79db9e34dd9786c5e",\n\t\t\t\t"fs": "9ee9cb5e5be06259a770856bd2f29435de07402acb3e5ed4ceedf2e5cf2c190f"\n\t\t\t},\n\t\t\t"may_cancel": true,\n\t\t\t"err": "",\n\t\t\t"location": "n1"\n\t\t}\n\t}" http_code=202 t=2022-02-07T12:25:16+0100 lvl=dbug msg="Got operation from LXD" t=2022-02-07T12:25:16+0100 lvl=dbug msg="\n\t{\n\t\t"id": "40a69811-161f-4702-8524-7d3839a2d183",\n\t\t"class": "websocket",\n\t\t"description": "Migrating instance",\n\t\t"created_at": "2022-02-07T12:25:16.716237873+01:00",\n\t\t"updated_at": "2022-02-07T12:25:16.716237873+01:00",\n\t\t"status": "Running",\n\t\t"status_code": 103,\n\t\t"resources": {\n\t\t\t"containers": [\n\t\t\t\t"/1.0/containers/test1"\n\t\t\t],\n\t\t\t"instances": [\n\t\t\t\t"/1.0/instances/test1"\n\t\t\t]\n\t\t},\n\t\t"metadata": {\n\t\t\t"control": "83a8754d01d70515f4e1af892c91676b897d257a7626bae79db9e34dd9786c5e",\n\t\t\t"fs": "9ee9cb5e5be06259a770856bd2f29435de07402acb3e5ed4ceedf2e5cf2c190f"\n\t\t},\n\t\t"may_cancel": true,\n\t\t"err": "",\n\t\t"location": "n1"\n\t}" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Connected to the websocket: wss://10.0.1.31:8443/1.0/events?project=default&target=n2" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Sending request to LXD" etag= method=POST url="https://10.0.1.31:8443/1.0/instances?project=default&target=n2" t=2022-02-07T12:25:16+0100 lvl=dbug msg="\n\t{\n\t\t"architecture": "x86_64",\n\t\t"config": {\n\t\t\t"image.architecture": "amd64",\n\t\t\t"image.description": "Alpine edge amd64 (20220201_13:00)",\n\t\t\t"image.os": "Alpine",\n\t\t\t"image.release": "edge",\n\t\t\t"image.serial": "20220201_13:00",\n\t\t\t"image.type": "squashfs",\n\t\t\t"image.variant": "default",\n\t\t\t"volatile.base_image": "859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee",\n\t\t\t"volatile.eth0.hwaddr": "00:16:3e:2f:90:a7",\n\t\t\t"volatile.idmap.base": "0",\n\t\t\t"volatile.idmap.current": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t"volatile.idmap.next": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t"volatile.last_state.idmap": "[{\"Isuid\":true,\"Isgid\":false,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000},{\"Isuid\":false,\"Isgid\":true,\"Hostid\":1000000,\"Nsid\":0,\"Maprange\":1000000000}]",\n\t\t\t"volatile.last_state.power": "STOPPED",\n\t\t\t"volatile.uuid": "3c09669f-77ac-4060-8231-4461906378a9"\n\t\t},\n\t\t"devices": {},\n\t\t"ephemeral": false,\n\t\t"profiles": [\n\t\t\t"default"\n\t\t],\n\t\t"stateful": false,\n\t\t"description": "",\n\t\t"name": "lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9",\n\t\t"source": {\n\t\t\t"type": "migration",\n\t\t\t"certificate": "-----BEGIN CERTIFICATE-----\nMIIB9zCCAX2gAwIBAgIQAKR8eYGnbF+EvD3i0Q2/czAKBggqhkjOPQQDAzAwMRww\nGgYDVQQKExNsaW51eGNvbnRhaW5lcnMub3JnMRAwDgYDVQQDDAdyb290QG4xMB4X\nDTIyMDIwMjE4NTEwNloXDTMyMDEzMTE4NTEwNlowMDEcMBoGA1UEChMTbGludXhj\nb250YWluZXJzLm9yZzEQMA4GA1UEAwwHcm9vdEBuMTB2MBAGByqGSM49AgEGBSuB\nBAAiA2IABJ92bn9+Zafi3DNlQ1C21Zew9oKMRCZTQUHA2G9U7ZTVqli76qOGUc4n\nfAcasrnXOGkPP4AmbQYeoZSewuRHi2Tv0sjQBnrKOr1gnNXvFBnKcFYptyRTIf3n\nCj6d1YF57qNcMFowDgYDVR0PAQH/BAQDAgWgMBMGA1UdJQQMMAoGCCsGAQUFBwMB\nMAwGA1UdEwEB/wQCMAAwJQYDVR0RBB4wHIICbjGHBH8AAAGHEAAAAAAAAAAAAAAA\nAAAAAAEwCgYIKoZIzj0EAwMDaAAwZQIxAMFPCl+cVhLJ/wEt+t9VE3dbcIs/qtFV\nlO3y/FeYBqju1Z1pcW80K/4lL+NU+1ZdiAIwAc6pef1thBUpauxvLUfdikMQbIgX\n2B07zaER8uITxdN7iWtAz9mmtpqF4H1Yf9HX\n-----END CERTIFICATE-----\n",\n\t\t\t"base-image": "859a0a6696a0ef4554edb9d4519dbd73fcf268512472a353afaca5c6fbe96eee",\n\t\t\t"mode": "pull",\n\t\t\t"operation": "https://10.0.1.30:8443/1.0/operations/40a69811-161f-4702-8524-7d3839a2d183",\n\t\t\t"secrets": {\n\t\t\t\t"control": "83a8754d01d70515f4e1af892c91676b897d257a7626bae79db9e34dd9786c5e",\n\t\t\t\t"fs": "9ee9cb5e5be06259a770856bd2f29435de07402acb3e5ed4ceedf2e5cf2c190f"\n\t\t\t},\n\t\t\t"allow_inconsistent": false\n\t\t},\n\t\t"instance_type": "",\n\t\t"type": "container"\n\t}" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Allowing untrusted GET" ip=10.0.1.31:35864 url="/1.0/operations/40a69811-161f-4702-8524-7d3839a2d183/websocket?secret=83a8754d01d70515f4e1af892c91676b897d257a7626bae79db9e34dd9786c5e" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Connected websocket Operation: 40a69811-161f-4702-8524-7d3839a2d183" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Handled websocket Operation: 40a69811-161f-4702-8524-7d3839a2d183" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Allowing untrusted GET" ip=10.0.1.31:35866 url="/1.0/operations/40a69811-161f-4702-8524-7d3839a2d183/websocket?secret=9ee9cb5e5be06259a770856bd2f29435de07402acb3e5ed4ceedf2e5cf2c190f" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Connected websocket Operation: 40a69811-161f-4702-8524-7d3839a2d183" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Handled websocket Operation: 40a69811-161f-4702-8524-7d3839a2d183" t=2022-02-07T12:25:16+0100 lvl=info msg="Migration channels connected" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Got operation from LXD" t=2022-02-07T12:25:16+0100 lvl=dbug msg="\n\t{\n\t\t"id": "c1677123-e7cd-4ce1-85ef-d6a7c61f6b6d",\n\t\t"class": "task",\n\t\t"description": "Creating instance",\n\t\t"created_at": "2022-02-07T12:25:16.905830258+01:00",\n\t\t"updated_at": "2022-02-07T12:25:16.905830258+01:00",\n\t\t"status": "Running",\n\t\t"status_code": 103,\n\t\t"resources": {\n\t\t\t"containers": [\n\t\t\t\t"/1.0/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9"\n\t\t\t],\n\t\t\t"instances": [\n\t\t\t\t"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9"\n\t\t\t]\n\t\t},\n\t\t"metadata": null,\n\t\t"may_cancel": false,\n\t\t"err": "",\n\t\t"location": "n2"\n\t}" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Sending request to LXD" etag= method=GET url="https://10.0.1.31:8443/1.0/operations/c1677123-e7cd-4ce1-85ef-d6a7c61f6b6d?project=default&target=n2" t=2022-02-07T12:25:16+0100 lvl=dbug msg="Got response struct from LXD" t=2022-02-07T12:25:16+0100 lvl=dbug msg="\n\t{\n\t\t"id": "c1677123-e7cd-4ce1-85ef-d6a7c61f6b6d",\n\t\t"class": "task",\n\t\t"description": "Creating instance",\n\t\t"created_at": "2022-02-07T12:25:16.905830258+01:00",\n\t\t"updated_at": "2022-02-07T12:25:16.905830258+01:00",\n\t\t"status": "Running",\n\t\t"status_code": 103,\n\t\t"resources": {\n\t\t\t"containers": [\n\t\t\t\t"/1.0/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9"\n\t\t\t],\n\t\t\t"instances": [\n\t\t\t\t"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9"\n\t\t\t]\n\t\t},\n\t\t"metadata": null,\n\t\t"may_cancel": false,\n\t\t"err": "",\n\t\t"location": "n2"\n\t}" t=2022-02-07T12:25:17+0100 lvl=dbug msg="MigrateInstance started" args="&{Name:test1 Snapshots:[] MigrationType:{FSType:ZFS Features:[compress]} TrackProgress:true MultiSync:false FinalSync:false Data: ContentType: AllowInconsistent:false}" driver=zfs instance=test1 pool=local project=default t=2022-02-07T12:25:17+0100 lvl=dbug msg="MigrateInstance finished" args="&{Name:test1 Snapshots:[] MigrationType:{FSType:ZFS Features:[compress]} TrackProgress:true MultiSync:false FinalSync:false Data: ContentType: AllowInconsistent:false}" driver=zfs instance=test1 pool=local project=default t=2022-02-07T12:25:17+0100 lvl=dbug msg="Success for websocket operation: 40a69811-161f-4702-8524-7d3839a2d183" t=2022-02-07T12:25:17+0100 lvl=dbug msg="Updated metadata for task Operation: 5eef458d-ee01-456d-abf2-2387b0752ea5" t=2022-02-07T12:25:17+0100 lvl=dbug msg="Sending request to LXD" etag= method=DELETE url="https://10.0.1.30:8443/1.0/instances/test1?project=default" t=2022-02-07T12:25:17+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org" t=2022-02-07T12:25:17+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:34536 method=DELETE protocol=cluster url="/1.0/instances/test1?project=default" username= t=2022-02-07T12:25:17+0100 lvl=dbug msg="New task Operation: e381940f-4f08-4e8a-a3e4-51801ffa67be" t=2022-02-07T12:25:17+0100 lvl=dbug msg="Started task operation: e381940f-4f08-4e8a-a3e4-51801ffa67be" t=2022-02-07T12:25:17+0100 lvl=info msg="Deleting container" created=2022-02-07T11:24:03+0000 ephemeral=false instance=test1 instanceType=container project=default used=1970-01-01T00:00:00+0000 t=2022-02-07T12:25:17+0100 lvl=dbug msg="WriteJSON\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/e381940f-4f08-4e8a-a3e4-51801ffa67be",\n\t\t"error_code": 0,\n\t\t"error": "",\n\t\t"metadata": {\n\t\t\t"id": "e381940f-4f08-4e8a-a3e4-51801ffa67be",\n\t\t\t"class": "task",\n\t\t\t"description": "Deleting instance",\n\t\t\t"created_at": "2022-02-07T12:25:17.945248887+01:00",\n\t\t\t"updated_at": "2022-02-07T12:25:17.945248887+01: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/containers/test1"\n\t\t\t\t],\n\t\t\t\t"instances": [\n\t\t\t\t\t"/1.0/instances/test1"\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": "n1"\n\t\t}\n\t}" http_code=202 t=2022-02-07T12:25:17+0100 lvl=dbug msg="Got operation from LXD" t=2022-02-07T12:25:17+0100 lvl=dbug msg="\n\t{\n\t\t"id": "e381940f-4f08-4e8a-a3e4-51801ffa67be",\n\t\t"class": "task",\n\t\t"description": "Deleting instance",\n\t\t"created_at": "2022-02-07T12:25:17.945248887+01:00",\n\t\t"updated_at": "2022-02-07T12:25:17.945248887+01:00",\n\t\t"status": "Running",\n\t\t"status_code": 103,\n\t\t"resources": {\n\t\t\t"containers": [\n\t\t\t\t"/1.0/containers/test1"\n\t\t\t],\n\t\t\t"instances": [\n\t\t\t\t"/1.0/instances/test1"\n\t\t\t]\n\t\t},\n\t\t"metadata": null,\n\t\t"may_cancel": false,\n\t\t"err": "",\n\t\t"location": "n1"\n\t}" t=2022-02-07T12:25:17+0100 lvl=dbug msg="Sending request to LXD" etag= method=GET url="https://10.0.1.30:8443/1.0/operations/e381940f-4f08-4e8a-a3e4-51801ffa67be?project=default" t=2022-02-07T12:25:17+0100 lvl=dbug msg="Matched trusted cert" fingerprint=02a952d5d9504c0042087c71a83b0dd98f9d3f2b3b853661521e2d5076913ddf subject="CN=root@n1,O=linuxcontainers.org" t=2022-02-07T12:25:17+0100 lvl=dbug msg="Handling API request" ip=10.0.1.30:34538 method=GET protocol=cluster url="/1.0/operations/e381940f-4f08-4e8a-a3e4-51801ffa67be?project=default" username= t=2022-02-07T12:25:17+0100 lvl=dbug msg="WriteJSON\n\t{\n\t\t"type": "sync",\n\t\t"status": "Success",\n\t\t"status_code": 200,\n\t\t"operation": "",\n\t\t"error_code": 0,\n\t\t"error": "",\n\t\t"metadata": {\n\t\t\t"id": "e381940f-4f08-4e8a-a3e4-51801ffa67be",\n\t\t\t"class": "task",\n\t\t\t"description": "Deleting instance",\n\t\t\t"created_at": "2022-02-07T12:25:17.945248887+01:00",\n\t\t\t"updated_at": "2022-02-07T12:25:17.945248887+01: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/containers/test1"\n\t\t\t\t],\n\t\t\t\t"instances": [\n\t\t\t\t\t"/1.0/instances/test1"\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": "n1"\n\t\t}\n\t}" http_code=200 t=2022-02-07T12:25:18+0100 lvl=dbug msg="Got response struct from LXD" t=2022-02-07T12:25:18+0100 lvl=dbug msg="\n\t{\n\t\t"id": "e381940f-4f08-4e8a-a3e4-51801ffa67be",\n\t\t"class": "task",\n\t\t"description": "Deleting instance",\n\t\t"created_at": "2022-02-07T12:25:17.945248887+01:00",\n\t\t"updated_at": "2022-02-07T12:25:17.945248887+01:00",\n\t\t"status": "Running",\n\t\t"status_code": 103,\n\t\t"resources": {\n\t\t\t"containers": [\n\t\t\t\t"/1.0/containers/test1"\n\t\t\t],\n\t\t\t"instances": [\n\t\t\t\t"/1.0/instances/test1"\n\t\t\t]\n\t\t},\n\t\t"metadata": null,\n\t\t"may_cancel": false,\n\t\t"err": "",\n\t\t"location": "n1"\n\t}" t=2022-02-07T12:25:18+0100 lvl=dbug msg="DeleteInstance started" driver=zfs instance=test1 pool=local project=default t=2022-02-07T12:25:18+0100 lvl=dbug msg="Deleting instance volume" driver=zfs instance=test1 pool=local project=default volName=test1 t=2022-02-07T12:25:18+0100 lvl=dbug msg="DeleteInstance finished" driver=zfs instance=test1 pool=local project=default t=2022-02-07T12:25:18+0100 lvl=info msg="Deleted container" created=2022-02-07T11:24:03+0000 ephemeral=false instance=test1 instanceType=container project=default used=1970-01-01T00:00:00+0000 t=2022-02-07T12:25:18+0100 lvl=dbug msg="Success for task operation: e381940f-4f08-4e8a-a3e4-51801ffa67be" t=2022-02-07T12:25:18+0100 lvl=dbug msg="Sending request to LXD" etag= method=POST url="https://10.0.1.31:8443/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9?project=default&target=n2" t=2022-02-07T12:25:18+0100 lvl=dbug msg="\n\t{\n\t\t"name": "test1",\n\t\t"migration": false,\n\t\t"live": false,\n\t\t"instance_only": false,\n\t\t"container_only": false,\n\t\t"target": null,\n\t\t"pool": "",\n\t\t"project": ""\n\t}" t=2022-02-07T12:25:18+0100 lvl=dbug msg="Got operation from LXD" t=2022-02-07T12:25:18+0100 lvl=dbug msg="\n\t{\n\t\t"id": "a3dd4210-0660-4049-8edf-dad5406a51e9",\n\t\t"class": "task",\n\t\t"description": "Renaming instance",\n\t\t"created_at": "2022-02-07T12:25:18.176093831+01:00",\n\t\t"updated_at": "2022-02-07T12:25:18.176093831+01:00",\n\t\t"status": "Running",\n\t\t"status_code": 103,\n\t\t"resources": {\n\t\t\t"containers": [\n\t\t\t\t"/1.0/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9"\n\t\t\t],\n\t\t\t"instances": [\n\t\t\t\t"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9"\n\t\t\t]\n\t\t},\n\t\t"metadata": null,\n\t\t"may_cancel": false,\n\t\t"err": "",\n\t\t"location": "n2"\n\t}" t=2022-02-07T12:25:18+0100 lvl=dbug msg="Sending request to LXD" etag= method=GET url="https://10.0.1.31:8443/1.0/operations/a3dd4210-0660-4049-8edf-dad5406a51e9?project=default&target=n2" t=2022-02-07T12:25:18+0100 lvl=dbug msg="Got response struct from LXD" t=2022-02-07T12:25:18+0100 lvl=dbug msg="\n\t{\n\t\t"id": "a3dd4210-0660-4049-8edf-dad5406a51e9",\n\t\t"class": "task",\n\t\t"description": "Renaming instance",\n\t\t"created_at": "2022-02-07T12:25:18.176093831+01:00",\n\t\t"updated_at": "2022-02-07T12:25:18.176093831+01:00",\n\t\t"status": "Running",\n\t\t"status_code": 103,\n\t\t"resources": {\n\t\t\t"containers": [\n\t\t\t\t"/1.0/containers/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9"\n\t\t\t],\n\t\t\t"instances": [\n\t\t\t\t"/1.0/instances/lxd-move-of-3c09669f-77ac-4060-8231-4461906378a9"\n\t\t\t]\n\t\t},\n\t\t"metadata": null,\n\t\t"may_cancel": false,\n\t\t"err": "",\n\t\t"location": "n2"\n\t}" t=2022-02-07T12:25:18+0100 lvl=dbug msg="Success for task operation: 5eef458d-ee01-456d-abf2-2387b0752ea5" t=2022-02-07T12:25:18+0100 lvl=dbug msg="Event listener server handler stopped" listener=74ded8f9-25d6-41d0-87ff-39ac10677f31 local=/var/snap/lxd/common/lxd/unix.socket localOnly=false remote=@ t=2022-02-07T12:25:21+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.33:8443 t=2022-02-07T12:25:21+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.33:8443 t=2022-02-07T12:25:21+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443 t=2022-02-07T12:25:21+0100 lvl=dbug msg="Completed heartbeat round" duration=6.776931646s local=10.0.1.30:8443 t=2022-02-07T12:25:23+0100 lvl=dbug msg="Database error: &fmt.wrapError{msg:"Delete \"operations\": database is locked", err:protocol.Error{Code:5, Message:"database is locked"}}" t=2022-02-07T12:25:23+0100 lvl=dbug msg="Retry failed db interaction (Delete "operations": database is locked)" t=2022-02-07T12:25:24+0100 lvl=dbug msg="Starting heartbeat round" local=10.0.1.30:8443 mode=normal t=2022-02-07T12:25:24+0100 lvl=dbug msg="Heartbeat updating local raft members" members="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:voter} Name:n2} {NodeInfo:{ID:3 Address:10.0.1.33:8443 Role:voter} Name:n3}]" t=2022-02-07T12:25:26+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.31:8443 t=2022-02-07T12:25:26+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.31:8443 t=2022-02-07T12:25:27+0100 lvl=dbug msg="Sending heartbeat request" address=10.0.1.33:8443 t=2022-02-07T12:25:27+0100 lvl=dbug msg="Successful heartbeat" remote=10.0.1.33:8443 t=2022-02-07T12:25:27+0100 lvl=dbug msg="Rebalancing member roles in heartbeat" local=10.0.1.30:8443 t=2022-02-07T12:25:27+0100 lvl=dbug msg="Completed heartbeat round" duration=2.58084135s local=10.0.1.30:8443 t=2022-02-07T12:25:34+0100 lvl=dbug msg="Starting heartbeat round" local=10.0.1.30:8443 mode=normal t=2022-02-07T12:25:34+0100 lvl=dbug msg="Heartbeat updating local raft members" members="[{NodeInfo:{ID:1 Address:10.0.1.30:8443 Role:voter} Name:n1} {NodeInfo:{ID:2 Address:10.0.1.31:8443 Role:voter} Name:n2} {NodeInfo:{ID:3 Address:10.0.1.33:8443 Role:voter} Name:n3}]"

Feb 07 '22 11:02 kriszos

Is it possible you are saturating your link preventing the DB operations from progressing in a timely manner?

Although I suppose the transfer hasn't started yet.

Feb 07 '22 11:02 tomponline

my test environment are virtual machines on the same host connected to single bridge. It is very unlikely that link is saturated.

Feb 07 '22 12:02 kriszos

Thanks for this info. I've reproduced this exact issue, investigating now...

Feb 07 '22 14:02 tomponline

Thanks, I am looking forward to resolution of this issue. Let me know if you need anything else.

Feb 07 '22 15:02 kriszos

So looking into this, I believe this is simply caused by time it takes for the target member to perform the necessary DB queries across the network to the member with the DB leader role. When the network has latency, this increases the time it takes to run all of those queries (there are quite a lot!) and this can take more than 10s, after which the source gives up waiting for the target to connect to it to pull the source instance from it.

Its taking a long time in the CreateInternal function and I can see its taking several seconds between each logical step in that function.

@stgraber is this something we want to cater for? It feels like if we are going to want to allow clusters to operate over high latency (relative to LAN) networks then we will need to be a lot more frugal with the number of DB queries we run and/or send some top-level requests (like create instance DB records) as a single logical request to the leader and have it run the multiple DB queries locally.

Feb 07 '22 15:02 tomponline

Removing the bug label, as its not clear at this time whether we are supporting this type of latency. The reason 4.20 started seeing this issue is that it added a reasonable (IMHO) 10s max time for the target member to start the transfer (whereas previously there was no timeout - which I consider to be a network programming no-no). Even over a high latency link 10s should be sufficient, but is not due to the number of queries being done from the target member to the leader member.

Feb 07 '22 15:02 tomponline

There are likely lots of these sorts of operations that we should optimise to provide reasonable utility over a high latency link (most of them won't have timeouts, but will be intolerably slow).

Feb 07 '22 15:02 tomponline

We had a quick chat with @tomponline on this, the conclusion was that LXD cluster is normally designed for operation within one rack, so in general server to server latency of less than 1ms.

That said, such issues do point out lack of optimization on some database requests which we could and should easily improve. We won't be committing to making a 40ms server to server latency work, but if the result of improving some of those database interactions get you there, that's great for everyone :)

Feb 07 '22 18:02 stgraber

That's a shame. Please do add information about latency limitation to documentation of clustering. Could you elaborate why latency is even relevant with lxd clusters. As far as I can see the only thing cluster does is syncing information about location of instances and configuration (profiles, networks etc). Storage is separate on every node unless you use ceph which configuration and management is outside of lxd scope. Live migration and instant failover of containers is unfortunately still not possible. I have to figure out how to sync configuration changes across non-clustered nodes. Do you have any advice? My goal was to provide seamless experience of moving workload closer to clients without having to configure node by hand every time I add new one or make configuration change. Anyway thank you for looking into this issue, I hope this will help You improve lxd overall.

Feb 07 '22 19:02 kriszos

In a LXD cluster, the database is shared with all servers. As it's HA, every write needs to reach at least two servers to go through (and eventually reach three servers). Only one of the LXD servers will act as the database leader, that's the server which actually processes all database queries, it then sends writes to two other servers, when one of the two confirms the write, then it moves on.

So say you have one server which is 40ms away from the database leader which is itself 40ms away from the other two servers that the database replicates to, then every single DB read will take a minimum of 40ms and every DB write will take a minimum of 80ms.

Considering that a complex operation like a migration requires to pull data at various levels (projects, instances, storage pools, operations, ...), you can easily get over a dozen DB transactions meaning at least that many round trips to the DB leader with some of those being write operations requiring the additional delay.

The 40ms/80ms is also assuming a best case scenario where an entire request can fit in one packet (1500 bytes on wire), when that's not the case, then the delay will increase as the request and response will be fragmented.

Feb 07 '22 20:02 stgraber

Ive removed a few more unnecessary db queries recently as part of moving storage db record management into the storage package so will revalidate if that's improved things.

Mar 31 '22 20:03 tomponline

@tomponline did some tests to check if there was any improvements after your changes. I tested on the same environment as before but upgraded to version 5.1. Unfortunately there was no improvements.

May 04 '22 09:05 kriszos

Still a problem with LXD 5.7. Dqlite over WAN isn't optimal.

Oct 26 '22 14:10 tomponline

@stgraber happy to close this one, or shall we spend more time trying to reduce the number of queries involved with cluster migration?

Nov 17 '22 16:11 tomponline