search

canonical / lxd

Powerful system container and virtual machine manager
https://canonical.com/lxd
GNU Affero General Public License v3.0
4.32k stars 926 forks source link

lxc move for virtual machines broken in 5.1 and ZFS storage backend #10435

Closed phiser678 closed 2 years ago

phiser678 commented 2 years ago

Required information

Issue description

In a cluster setup I can move a container, but not a VM. This is the error:

Error: Copy instance operation failed: Failed instance creation: Error transferring instance data: Failed decoding migration header: invalid character '\x00' looking for beginning of value

All members have the same Intel architecture.

Steps to reproduce

  1. Default setup for cluster with ZFS as storage
  2. snap set lxd criu=enable;apt install criu;systemctl restart snap.lxd.daemon on all members
  3. lxc profile set default cluster.evacuate migrate
  4. lxc init images:ubuntu/focal c1 --vm
  5. lxc move c1 --target=testpc16

Information to attach

log of monitor:

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'New task Operation: aa671deb-e631-48cf-98f7-8f084875bbe3'
timestamp: "2022-05-19T10:09:43.860592316+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'Started task operation: aa671deb-e631-48cf-98f7-8f084875bbe3'
timestamp: "2022-05-19T10:09:43.862049938+02:00"
type: logging

location: testpc15
metadata:
  class: task
  created_at: "2022-05-19T10:09:43.854965031+02:00"
  description: Migrating instance
  err: ""
  id: aa671deb-e631-48cf-98f7-8f084875bbe3
  location: testpc15
  may_cancel: false
  metadata: null
  resources:
    instances:
    - /1.0/instances/c1
  status: Pending
  status_code: 105
  updated_at: "2022-05-19T10:09:43.854965031+02:00"
project: default
timestamp: "2022-05-19T10:09:43.862017557+02:00"
type: operation

location: testpc15
metadata:
  class: task
  created_at: "2022-05-19T10:09:43.854965031+02:00"
  description: Migrating instance
  err: ""
  id: aa671deb-e631-48cf-98f7-8f084875bbe3
  location: testpc15
  may_cancel: false
  metadata: null
  resources:
    instances:
    - /1.0/instances/c1
  status: Running
  status_code: 103
  updated_at: "2022-05-19T10:09:43.854965031+02:00"
project: default
timestamp: "2022-05-19T10:09:43.863177092+02:00"
type: operation

location: testpc15
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0/operations/aa671deb-e631-48cf-98f7-8f084875bbe3?target=testpc16
    username: root
  level: debug
  message: Handling API request
timestamp: "2022-05-19T10:09:43.869566557+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: Connecting to a remote LXD over HTTPS
timestamp: "2022-05-19T10:09:43.876694854+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: Connecting to a remote LXD over HTTPS
timestamp: "2022-05-19T10:09:43.884113173+02:00"
type: logging

location: testpc15
metadata:
  context:
    etag: ""
    method: GET
    url: https://192.168.41.244:8443/1.0/instances/c1?project=default
  level: debug
  message: Sending request to LXD
timestamp: "2022-05-19T10:09:43.891588734+02:00"
type: logging

location: testpc15
metadata:
  context:
    fingerprint: dc783b47da1849e5b53f17001a174039b341c214b65ef79b29587b2f3d62385d
    ip: 192.168.41.244:48190
    method: GET
    protocol: cluster
    url: /1.0/instances/c1?project=default
  level: debug
  message: Handling API request
timestamp: "2022-05-19T10:09:43.905232955+02:00"
type: logging

location: testpc15
metadata:
  context:
    fingerprint: dc783b47da1849e5b53f17001a174039b341c214b65ef79b29587b2f3d62385d
    subject: CN=root@testpc15,O=linuxcontainers.org
  level: debug
  message: Matched trusted cert
timestamp: "2022-05-19T10:09:43.905168879+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: Got response struct from LXD
timestamp: "2022-05-19T10:09:43.919175626+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  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\": \"Ubuntu focal amd64 (20220518_07:42)\",\n\t\t\t\"image.os\":
    \"Ubuntu\",\n\t\t\t\"image.release\": \"focal\",\n\t\t\t\"image.serial\": \"20220518_07:42\",\n\t\t\t\"image.type\":
    \"disk-kvm.img\",\n\t\t\t\"image.variant\": \"default\",\n\t\t\t\"volatile.apply_template\":
    \"create\",\n\t\t\t\"volatile.base_image\": \"b82f1d3f42dfe5001d7b8b9415f940206d4669a44a6599cbf9455ea62e960b12\",\n\t\t\t\"volatile.cloud-init.instance-id\":
    \"5754c0a8-3cf9-40c0-8066-9a9e3f0d360a\",\n\t\t\t\"volatile.eth0.hwaddr\": \"00:16:3e:06:99:13\",\n\t\t\t\"volatile.uuid\":
    \"6be7a89e-0c2c-47a8-adac-c5b8ebe05ae7\"\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-05-19T08:09:28.847392541Z\",\n\t\t\"expanded_config\":
    {\n\t\t\t\"cluster.evacuate\": \"migrate\",\n\t\t\t\"image.architecture\": \"amd64\",\n\t\t\t\"image.description\":
    \"Ubuntu focal amd64 (20220518_07:42)\",\n\t\t\t\"image.os\": \"Ubuntu\",\n\t\t\t\"image.release\":
    \"focal\",\n\t\t\t\"image.serial\": \"20220518_07:42\",\n\t\t\t\"image.type\":
    \"disk-kvm.img\",\n\t\t\t\"image.variant\": \"default\",\n\t\t\t\"volatile.apply_template\":
    \"create\",\n\t\t\t\"volatile.base_image\": \"b82f1d3f42dfe5001d7b8b9415f940206d4669a44a6599cbf9455ea62e960b12\",\n\t\t\t\"volatile.cloud-init.instance-id\":
    \"5754c0a8-3cf9-40c0-8066-9a9e3f0d360a\",\n\t\t\t\"volatile.eth0.hwaddr\": \"00:16:3e:06:99:13\",\n\t\t\t\"volatile.uuid\":
    \"6be7a89e-0c2c-47a8-adac-c5b8ebe05ae7\"\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\":
    \"eth0\",\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\":
    \"c1\",\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\": \"testpc15\",\n\t\t\"type\": \"virtual-machine\",\n\t\t\"project\":
    \"default\"\n\t}"
timestamp: "2022-05-19T10:09:43.919322383+02:00"
type: logging

location: testpc15
metadata:
  context:
    fingerprint: dc783b47da1849e5b53f17001a174039b341c214b65ef79b29587b2f3d62385d
    subject: CN=root@testpc15,O=linuxcontainers.org
  level: debug
  message: Matched trusted cert
timestamp: "2022-05-19T10:09:43.942109091+02:00"
type: logging

location: testpc15
metadata:
  context:
    fingerprint: dc783b47da1849e5b53f17001a174039b341c214b65ef79b29587b2f3d62385d
    ip: 192.168.41.244:48194
    method: GET
    protocol: cluster
    url: /1.0/events?project=default
  level: debug
  message: Handling API request
timestamp: "2022-05-19T10:09:43.942188431+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'Connected to the websocket: wss://192.168.41.244:8443/1.0/events?project=default'
timestamp: "2022-05-19T10:09:43.943631466+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  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\t\"allow_inconsistent\": false\n\t}"
timestamp: "2022-05-19T10:09:43.943746815+02:00"
type: logging

location: testpc15
metadata:
  context:
    etag: ""
    method: POST
    url: https://192.168.41.244:8443/1.0/instances/c1?project=default
  level: debug
  message: Sending request to LXD
timestamp: "2022-05-19T10:09:43.943686825+02:00"
type: logging

location: testpc15
metadata:
  context:
    listener: 5fd9bfe8-4bdb-4daa-85be-02899c4549d8
    local: 192.168.41.244:8443
    remote: 192.168.41.244:48194
  level: debug
  message: Event listener server handler started
timestamp: "2022-05-19T10:09:43.94644332+02:00"
type: logging

location: testpc15
metadata:
  context:
    fingerprint: dc783b47da1849e5b53f17001a174039b341c214b65ef79b29587b2f3d62385d
    subject: CN=root@testpc15,O=linuxcontainers.org
  level: debug
  message: Matched trusted cert
timestamp: "2022-05-19T10:09:43.965883273+02:00"
type: logging

location: testpc15
metadata:
  context:
    fingerprint: dc783b47da1849e5b53f17001a174039b341c214b65ef79b29587b2f3d62385d
    ip: 192.168.41.244:48196
    method: POST
    protocol: cluster
    url: /1.0/instances/c1?project=default
  level: debug
  message: Handling API request
timestamp: "2022-05-19T10:09:43.965961612+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'New websocket Operation: d47634d9-d567-48e8-8e98-150d16481c78'
timestamp: "2022-05-19T10:09:43.987888658+02:00"
type: logging

location: testpc15
metadata:
  class: websocket
  created_at: "2022-05-19T10:09:43.979599691+02:00"
  description: Migrating instance
  err: ""
  id: d47634d9-d567-48e8-8e98-150d16481c78
  location: testpc15
  may_cancel: true
  metadata:
    control: 6c4b49b5138424044269625bd6cb6a499efffeba86915636587986d5bd616e03
    fs: 9009a80e65a96077c06e232c0b66e8b9b70514fe43bc86a6edb14983b1ce46f0
  resources:
    instances:
    - /1.0/instances/c1
  status: Pending
  status_code: 105
  updated_at: "2022-05-19T10:09:43.979599691+02:00"
project: default
timestamp: "2022-05-19T10:09:43.989634514+02:00"
type: operation

location: testpc15
metadata:
  context: {}
  level: info
  message: Waiting for migration channel connections
timestamp: "2022-05-19T10:09:43.990008733+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'Started websocket operation: d47634d9-d567-48e8-8e98-150d16481c78'
timestamp: "2022-05-19T10:09:43.989671592+02:00"
type: logging

location: testpc15
metadata:
  class: websocket
  created_at: "2022-05-19T10:09:43.979599691+02:00"
  description: Migrating instance
  err: ""
  id: d47634d9-d567-48e8-8e98-150d16481c78
  location: testpc15
  may_cancel: true
  metadata:
    control: 6c4b49b5138424044269625bd6cb6a499efffeba86915636587986d5bd616e03
    fs: 9009a80e65a96077c06e232c0b66e8b9b70514fe43bc86a6edb14983b1ce46f0
  resources:
    instances:
    - /1.0/instances/c1
  status: Running
  status_code: 103
  updated_at: "2022-05-19T10:09:43.979599691+02:00"
project: default
timestamp: "2022-05-19T10:09:43.990737731+02:00"
type: operation

location: testpc15
metadata:
  context: {}
  level: debug
  message: Got operation from LXD
timestamp: "2022-05-19T10:09:43.992083013+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: "\n\t{\n\t\t\"id\": \"d47634d9-d567-48e8-8e98-150d16481c78\",\n\t\t\"class\":
    \"websocket\",\n\t\t\"description\": \"Migrating instance\",\n\t\t\"created_at\":
    \"2022-05-19T10:09:43.979599691+02:00\",\n\t\t\"updated_at\": \"2022-05-19T10:09:43.979599691+02:00\",\n\t\t\"status\":
    \"Running\",\n\t\t\"status_code\": 103,\n\t\t\"resources\": {\n\t\t\t\"instances\":
    [\n\t\t\t\t\"/1.0/instances/c1\"\n\t\t\t]\n\t\t},\n\t\t\"metadata\": {\n\t\t\t\"control\":
    \"6c4b49b5138424044269625bd6cb6a499efffeba86915636587986d5bd616e03\",\n\t\t\t\"fs\":
    \"9009a80e65a96077c06e232c0b66e8b9b70514fe43bc86a6edb14983b1ce46f0\"\n\t\t},\n\t\t\"may_cancel\":
    true,\n\t\t\"err\": \"\",\n\t\t\"location\": \"testpc15\"\n\t}"
timestamp: "2022-05-19T10:09:43.992126073+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'Connected to the websocket: wss://192.168.41.212:8443/1.0/events?project=default&target=testpc16'
timestamp: "2022-05-19T10:09:44.014036109+02:00"
type: logging

location: testpc15
metadata:
  context:
    etag: ""
    method: POST
    url: https://192.168.41.212:8443/1.0/instances?project=default&target=testpc16
  level: debug
  message: Sending request to LXD
timestamp: "2022-05-19T10:09:44.014109068+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  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\": \"Ubuntu focal amd64 (20220518_07:42)\",\n\t\t\t\"image.os\":
    \"Ubuntu\",\n\t\t\t\"image.release\": \"focal\",\n\t\t\t\"image.serial\": \"20220518_07:42\",\n\t\t\t\"image.type\":
    \"disk-kvm.img\",\n\t\t\t\"image.variant\": \"default\",\n\t\t\t\"volatile.apply_template\":
    \"create\",\n\t\t\t\"volatile.base_image\": \"b82f1d3f42dfe5001d7b8b9415f940206d4669a44a6599cbf9455ea62e960b12\",\n\t\t\t\"volatile.cloud-init.instance-id\":
    \"5754c0a8-3cf9-40c0-8066-9a9e3f0d360a\",\n\t\t\t\"volatile.eth0.hwaddr\": \"00:16:3e:06:99:13\",\n\t\t\t\"volatile.uuid\":
    \"6be7a89e-0c2c-47a8-adac-c5b8ebe05ae7\"\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-6be7a89e-0c2c-47a8-adac-c5b8ebe05ae7\",\n\t\t\"source\":
    {\n\t\t\t\"type\": \"migration\",\n\t\t\t\"certificate\": \"-----BEGIN CERTIFICATE-----\\nMIICCDCCAY+gAwIBAgIQCAIVeGApxSRNfEDBLn0uTjAKBggqhkjOPQQDAzA2MRww\\nGgYDVQQKExNsaW51eGNvbnRhaW5lcnMub3JnMRYwFAYDVQQDDA1yb290QHRlc3Rw\\nYzE1MB4XDTIyMDUxOTA3Mjk1NFoXDTMyMDUxNjA3Mjk1NFowNjEcMBoGA1UEChMT\\nbGludXhjb250YWluZXJzLm9yZzEWMBQGA1UEAwwNcm9vdEB0ZXN0cGMxNTB2MBAG\\nByqGSM49AgEGBSuBBAAiA2IABEfdxIeXD8HB+eB2hTGqrYUIlQpOFOLAbwS9rVZF\\ni6YfDW/2U26cizaVkJa5sNA+hIUmPSjNZiGlU/yt8oqsbgtq904EeZXLoLCQ9rGV\\njziu88nlKobRjUACaxC4BT+XKqNiMGAwDgYDVR0PAQH/BAQDAgWgMBMGA1UdJQQM\\nMAoGCCsGAQUFBwMBMAwGA1UdEwEB/wQCMAAwKwYDVR0RBCQwIoIIdGVzdHBjMTWH\\nBH8AAAGHEAAAAAAAAAAAAAAAAAAAAAEwCgYIKoZIzj0EAwMDZwAwZAIwUAR5yXbj\\nz6FINPHYDcbdEc5GlodV3Bvb+YTdSlwX9CaD88As6xMH+S2M6XwNuMQ9AjAqgupw\\nlpQP8eGWjpIt7Z2negeCpcxpPJAy/JDYDbQmsLuK7l9LaLOnp5OfzZ9+7zY=\\n-----END
    CERTIFICATE-----\\n\",\n\t\t\t\"base-image\": \"b82f1d3f42dfe5001d7b8b9415f940206d4669a44a6599cbf9455ea62e960b12\",\n\t\t\t\"mode\":
    \"pull\",\n\t\t\t\"operation\": \"https://192.168.41.244:8443/1.0/operations/d47634d9-d567-48e8-8e98-150d16481c78\",\n\t\t\t\"secrets\":
    {\n\t\t\t\t\"control\": \"6c4b49b5138424044269625bd6cb6a499efffeba86915636587986d5bd616e03\",\n\t\t\t\t\"fs\":
    \"9009a80e65a96077c06e232c0b66e8b9b70514fe43bc86a6edb14983b1ce46f0\"\n\t\t\t},\n\t\t\t\"allow_inconsistent\":
    false\n\t\t},\n\t\t\"instance_type\": \"\",\n\t\t\"type\": \"virtual-machine\"\n\t}"
timestamp: "2022-05-19T10:09:44.014288004+02:00"
type: logging

location: testpc16
metadata:
  action: instance-created
  source: /1.0/instances/lxd-move-of-6be7a89e-0c2c-47a8-adac-c5b8ebe05ae7
project: default
timestamp: "2022-05-19T10:09:44.073742995+02:00"
type: lifecycle

location: testpc16
metadata:
  class: task
  created_at: "2022-05-19T10:09:44.080501697+02:00"
  description: Creating instance
  err: ""
  id: caedfb4e-5945-46d2-9800-ad455a788a47
  location: testpc16
  may_cancel: false
  metadata: null
  resources:
    instances:
    - /1.0/instances/lxd-move-of-6be7a89e-0c2c-47a8-adac-c5b8ebe05ae7
  status: Pending
  status_code: 105
  updated_at: "2022-05-19T10:09:44.080501697+02:00"
project: default
timestamp: "2022-05-19T10:09:44.087656378+02:00"
type: operation

location: testpc16
metadata:
  class: task
  created_at: "2022-05-19T10:09:44.080501697+02:00"
  description: Creating instance
  err: ""
  id: caedfb4e-5945-46d2-9800-ad455a788a47
  location: testpc16
  may_cancel: false
  metadata: null
  resources:
    instances:
    - /1.0/instances/lxd-move-of-6be7a89e-0c2c-47a8-adac-c5b8ebe05ae7
  status: Running
  status_code: 103
  updated_at: "2022-05-19T10:09:44.080501697+02:00"
project: default
timestamp: "2022-05-19T10:09:44.088469422+02:00"
type: operation

location: testpc15
metadata:
  context: {}
  level: debug
  message: "\n\t{\n\t\t\"id\": \"caedfb4e-5945-46d2-9800-ad455a788a47\",\n\t\t\"class\":
    \"task\",\n\t\t\"description\": \"Creating instance\",\n\t\t\"created_at\": \"2022-05-19T10:09:44.080501697+02:00\",\n\t\t\"updated_at\":
    \"2022-05-19T10:09:44.080501697+02:00\",\n\t\t\"status\": \"Running\",\n\t\t\"status_code\":
    103,\n\t\t\"resources\": {\n\t\t\t\"instances\": [\n\t\t\t\t\"/1.0/instances/lxd-move-of-6be7a89e-0c2c-47a8-adac-c5b8ebe05ae7\"\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\": \"testpc16\"\n\t}"
timestamp: "2022-05-19T10:09:44.090016583+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: Got operation from LXD
timestamp: "2022-05-19T10:09:44.089928474+02:00"
type: logging

location: testpc15
metadata:
  context:
    etag: ""
    method: GET
    url: https://192.168.41.212:8443/1.0/operations/caedfb4e-5945-46d2-9800-ad455a788a47?project=default&target=testpc16
  level: debug
  message: Sending request to LXD
timestamp: "2022-05-19T10:09:44.090095553+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: Got response struct from LXD
timestamp: "2022-05-19T10:09:44.113143365+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: "\n\t{\n\t\t\"id\": \"caedfb4e-5945-46d2-9800-ad455a788a47\",\n\t\t\"class\":
    \"task\",\n\t\t\"description\": \"Creating instance\",\n\t\t\"created_at\": \"2022-05-19T10:09:44.080501697+02:00\",\n\t\t\"updated_at\":
    \"2022-05-19T10:09:44.080501697+02:00\",\n\t\t\"status\": \"Running\",\n\t\t\"status_code\":
    103,\n\t\t\"resources\": {\n\t\t\t\"instances\": [\n\t\t\t\t\"/1.0/instances/lxd-move-of-6be7a89e-0c2c-47a8-adac-c5b8ebe05ae7\"\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\": \"testpc16\"\n\t}"
timestamp: "2022-05-19T10:09:44.113224604+02:00"
type: logging

location: testpc15
metadata:
  context:
    ip: 192.168.41.212:53896
    url: /1.0/operations/d47634d9-d567-48e8-8e98-150d16481c78/websocket?secret=6c4b49b5138424044269625bd6cb6a499efffeba86915636587986d5bd616e03
  level: debug
  message: Allowing untrusted GET
timestamp: "2022-05-19T10:09:44.113676726+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'Connected websocket Operation: d47634d9-d567-48e8-8e98-150d16481c78'
timestamp: "2022-05-19T10:09:44.113780484+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'Handled websocket Operation: d47634d9-d567-48e8-8e98-150d16481c78'
timestamp: "2022-05-19T10:09:44.114035377+02:00"
type: logging

location: testpc15
metadata:
  context:
    ip: 192.168.41.212:53898
    url: /1.0/operations/d47634d9-d567-48e8-8e98-150d16481c78/websocket?secret=9009a80e65a96077c06e232c0b66e8b9b70514fe43bc86a6edb14983b1ce46f0
  level: debug
  message: Allowing untrusted GET
timestamp: "2022-05-19T10:09:44.128976606+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'Handled websocket Operation: d47634d9-d567-48e8-8e98-150d16481c78'
timestamp: "2022-05-19T10:09:44.129331569+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'Connected websocket Operation: d47634d9-d567-48e8-8e98-150d16481c78'
timestamp: "2022-05-19T10:09:44.129032521+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: info
  message: Migration channels connected
timestamp: "2022-05-19T10:09:44.129421699+02:00"
type: logging

location: testpc15
metadata:
  context:
    instance: c1
    project: default
  level: debug
  message: MountInstance started
timestamp: "2022-05-19T10:09:44.145262422+02:00"
type: logging

location: testpc15
metadata:
  context:
    dev: local/virtual-machines/c1.block
    driver: zfs
    pool: local
  level: debug
  message: Activated ZFS volume
timestamp: "2022-05-19T10:09:44.676662715+02:00"
type: logging

location: testpc15
metadata:
  context:
    instance: c1
    project: default
  level: debug
  message: MountInstance finished
timestamp: "2022-05-19T10:09:44.70232644+02:00"
type: logging

location: testpc15
metadata:
  context:
    dev: local/virtual-machines/c1
    driver: zfs
    path: /var/snap/lxd/common/lxd/storage-pools/local/virtual-machines/c1
    pool: local
  level: debug
  message: Mounted ZFS dataset
timestamp: "2022-05-19T10:09:44.702265612+02:00"
type: logging

location: testpc15
metadata:
  context:
    instance: c1
    project: default
  level: debug
  message: UnmountInstance started
timestamp: "2022-05-19T10:09:44.7032934+02:00"
type: logging

location: testpc15
metadata:
  context:
    dev: local/virtual-machines/c1
    driver: zfs
    path: /var/snap/lxd/common/lxd/storage-pools/local/virtual-machines/c1
    pool: local
    volName: c1
  level: debug
  message: Unmounted ZFS dataset
timestamp: "2022-05-19T10:09:44.724790335+02:00"
type: logging

location: testpc15
metadata:
  context:
    dev: local/virtual-machines/c1.block
    driver: zfs
    pool: local
    volName: c1
  level: debug
  message: Deactivated ZFS volume
timestamp: "2022-05-19T10:09:44.744529478+02:00"
type: logging

location: testpc15
metadata:
  context:
    instance: c1
    project: default
  level: debug
  message: UnmountInstance finished
timestamp: "2022-05-19T10:09:44.744563301+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'Set migration offer volume size for "c1": 10737418240'
timestamp: "2022-05-19T10:09:44.744579491+02:00"
type: logging

location: testpc15
metadata:
  context:
    args: '&{c1 [] {ZFS [migration_header compress]} true false false <nil>  false
      false}'
    instance: c1
    project: default
  level: debug
  message: MigrateInstance started
timestamp: "2022-05-19T10:09:44.747318214+02:00"
type: logging

location: testpc15
metadata:
  context: {}
  level: debug
  message: 'Updated metadata for task Operation: aa671deb-e631-48cf-98f7-8f084875bbe3'
timestamp: "2022-05-19T10:09:44.805530413+02:00"
type: logging

location: testpc16
metadata:
  class: task
  created_at: "2022-05-19T10:09:44.080501697+02:00"
  description: Creating instance
  err: 'Error transferring instance data: Failed decoding migration header: invalid
    character ''\x00'' looking for beginning of value'
  id: caedfb4e-5945-46d2-9800-ad455a788a47
  location: testpc16
  may_cancel: false
  metadata: null
  resources:
    instances:
    - /1.0/instances/lxd-move-of-6be7a89e-0c2c-47a8-adac-c5b8ebe05ae7
  status: Failure
  status_code: 400
  updated_at: "2022-05-19T10:09:44.080501697+02:00"
project: default
timestamp: "2022-05-19T10:09:44.805200684+02:00"
type: operation
tomponline commented 2 years ago

Looking into this.

tomponline commented 2 years ago

Confirmed this is a bug to do with optimized refresh (it only happens if transferring between ZFS pools on source and target).

It also occurs if doing lxc copy not just lxc move, and it leaves a zfs process running on the source:

lxc copy v1 home02:v1 -s zfs
Error: Failed instance creation: Error transferring instance data: Failed decoding migration header: invalid character '\x00' looking for beginning of value
zfs send -c -L zfs/virtual-machines/v1.block@migration-e69ebf6b-c18f-4043-9161-a4e31dc63650
tomponline commented 2 years ago

@monstermunchkin looks like another optimized refresh related bug.

phiser678 commented 2 years ago

Thank you for looking into this! I was wondering, is it possible to do a live migration with containers? Is there a work around if not supported? The members of my setup have all the same cpu, and I could do some debugging as well.

tomponline commented 2 years ago

@phiser678 CRIU is what provides live migration of containers, but it is very limited currently, in most scenarios it is not supported I'm afraid.

denogio commented 2 years ago

This is also a problem on 5.0/stable: Error: Failed instance creation: Error transferring instance data: Failed decoding migration header: invalid character '\x00' looking for beginning of value

tomponline commented 2 years ago

Reopening so we can track the addition of the tests as per https://github.com/lxc/lxd/pull/10489#pullrequestreview-991760143

stgraber commented 2 years ago

Test has been merged