text:
"lxc exec" frequently runs into I/O timeouts

Required information

Distribution: Ubuntu
Distribution version: 22.04 (in development)
The output of "lxc info":

config:
  core.https_address: '[::]'
  images.auto_update_interval: "24"
  images.remote_cache_expiry: "60"
  storage.lvm_thinpool_name: LXDPool
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
- network_state_ovn
- storage_volume_api_filtering
- image_restrictions
- storage_zfs_export
- network_dns_records
- storage_zfs_reserve_space
- network_acl_log
- storage_zfs_blocksize
- metrics_cpu_seconds
- instance_snapshot_never
- certificate_token
api_status: stable
api_version: "1.0"
auth: trusted
public: false
auth_methods:
- tls
environment:
  addresses:
  - 172.20.153.19:8443
  - '[2001:8b0:664:0:12d:8950:2717:8277]:8443'
  - 10.10.25.1:8443
  - 10.0.3.1:8443
  - 172.17.0.1:8443
  - 10.72.127.1:8443
  - 10.36.63.1:8443
  - 10.172.192.14:8443
  architectures:
  - x86_64
  - i686
  certificate: |
    -----BEGIN CERTIFICATE-----
    MIIGjDCCBHSgAwIBAgIQLf1ycWKsIfHRUbru8rWZujANBgkqhkiG9w0BAQsFADA2
    MRwwGgYDVQQKExNsaW51eGNvbnRhaW5lcnMub3JnMRYwFAYDVQQDDA1yb290QG5p
    ZWp3ZWluMB4XDTE2MDMyMjE1MTMwOVoXDTI2MDMyMDE1MTMwOVowNjEcMBoGA1UE
    ChMTbGludXhjb250YWluZXJzLm9yZzEWMBQGA1UEAwwNcm9vdEBuaWVqd2VpbjCC
    AiIwDQYJKoZIhvcNAQEBBQADggIPADCCAgoCggIBAJ6TXPWcmkUAh2lg+tHbLgqw
    J47kyIUX760E7BrpRqPyrIP9wtAqjdpazcX83GwbukgKkfFr/FRNv0/iP5rkbqq3
    ss92+Z2eOuqvQictrIaFcknwPjFC7P4RDE/UmRhMrdMd1jWNSFo1rT7HUHPMe2q9
    W3vdT8znj7U3blXuGtPgD8y8eNznJjdnjtwgx4F/70z5N2F4zD4OixrSLp7cluLx
    NdlLDdN5uMBxp9byY1QtrjkKHfdL8qBOifeQS544QGZgUGLfa5W5/DQvOQmji+NC
    f5UU2j7hbcOYA8S4CopM5jFwpX3X2oy/2tt2/JlAAKKYQtmFh3u7MAC2ndhN4TvO
    ukzYU9l+xvjSukeUc6f9m3TOpcn6zw9pR0iwFKlQsfQgUt7tcHZYfcKoq0Tczl2D
    /pa6vJNLaQ6i/8uYWcCyXuqZKvCl/WCoYVuu4xZc2VBXUPGwDDw6ukJlslVqoUTO
    gUVpNvSjAPAh8o0Vdks5UR60NMEVnMKryeBNJJ4qi8du3iCa3h2I2EWb6nCcj33t
    XW4Llrz3U5jl+UZncWPXitpAORxbP8VjnJWJPruT0P5a4jvafG0cfUkTFTolUJ6y
    31mohIYOrfLG5NDIU4YRxSxXRq4REbS3rjyhIox4ugFVcryZj8StvbU5TfhKQZWi
    aBISFxCtz21EQJI4Gy45AgMBAAGjggGUMIIBkDAOBgNVHQ8BAf8EBAMCBaAwEwYD
    VR0lBAwwCgYIKwYBBQUHAwEwDAYDVR0TAQH/BAIwADCCAVkGA1UdEQSCAVAwggFM
    gghuaWVqd2VpboIQMTcyLjIwLjE1My4xOS8yNYIpMjAwMTo4YjA6YmZmMjplYjE0
    OjQxZTI6NTQwZTo4MGYwOjFiZjIvNjSCKTIwMDE6OGIwOmJmZjI6ZWIxNDoyYzky
    OmY5MTc6OTJmZTpmYjc1LzY0gikyMDAxOjhiMDpiZmYyOmViMTQ6MTk3MjpmMWY2
    OjcxNTk6MmIxZC82NIIpMjAwMTo4YjA6YmZmMjplYjE0OjZhZjc6MjhmZjpmZWNj
    OmUzNDYvNjSCHGZlODA6OjZhZjc6MjhmZjpmZWNjOmUzNDYvNjSCCzEwLjAuMy4x
    LzI0ghxmZTgwOjpkMDg1OjIxZmY6ZmU5NTozMWI3LzY0ghtmZTgwOjpmYzE1OjRm
    ZjpmZThkOmE3NjkvNjSCHGZlODA6OmZjZTI6MjFmZjpmZTFlOjgwYzUvNjQwDQYJ
    KoZIhvcNAQELBQADggIBAJPdZjgcIIBT3UhuGjLWFda5/o9MSdEB2cl2ISo185D1
    tb7DGl3M7fUsu/N9VfMkz9QtP5R/sCYly3hyZLgKj5dz9c43BXwOMUdYaB+KShVB
    k7FE8s+V1VI2WCwXTtzHs5MgREe9TGMRg7BBzkat5m6gCIXhjO0jf2hdyuR/A4Z/
    RbAqh7jcDDHUZbdS/xBgE0eUfKsyAsDbru7JIBAfbrmUounwwLHzGycWpaxVBxqP
    3e3Zw6ousN9ELqvFs8nxz5UxUpmG3ynpwaZd3HULowrb+Fujjn+O+Ozwj7Uthgo7
    Hm+G8rVFPXxgK3mDkEAGfChPSga5QCfCOiyR7p3X4kLhZ2ONXFTHAWHIwvzMvmQm
    8nS233VygRb2+RFnzoFoIX9VWzGUtVzLm3kyNAw8esgGk7SKDGbhhGi6uQ5zK5q9
    7/zECXl6TFRKvm5CnIQW3maAA72mdLgfJBYsXecBpGqNtwKBHNvZ4BxQYoMHKu/i
    9CGuRyUNrAlACbWXFCcrl2dqZ/XfOXwXK9ln8xAWjYj1eQNks93YuBa7BDm3v2XH
    bYcD3BGs/ftUw2HMkWmwJG4BY3HKmT6QcayUGEWFT8oOA+BvNKakb0UYED4CKzh2
    DRGHayVJ5fsGw8Q5zni4YJTaGnhu7Clo5g3KhiNRL+FZX/r/u49WI5Or9xOPnOxL
    -----END CERTIFICATE-----
  certificate_fingerprint: 2a2f687296fb3e74ae352eb303843725690d16fd2b57fd373f44d46fbb8721d6
  driver: qemu | lxc
  driver_version: 6.1.1 | 4.0.12
  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.15.0-18-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: "22.04"
  project: default
  server: lxd
  server_clustered: false
  server_name: niejwein
  server_pid: 1763865
  server_version: "4.23"
  storage: zfs | btrfs
  storage_version: 2.0.6-1ubuntu3 | 5.4.1
  storage_supported_drivers:
  - name: dir
    version: "1"
    remote: false
  - name: lvm
    version: 2.03.07(2) (2019-11-30) / 1.02.167 (2019-11-30) / 4.45.0
    remote: false
  - name: zfs
    version: 2.0.6-1ubuntu3
    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

Issue description
I have lots of things that use lxc exec to run processes in a container, some of which run for a reasonably long time: for instance, I normally run Launchpad tests that way which can take anything up to hours, charmcraft uses it as part of preparing its build container, etc.  Until perhaps a couple of months ago this was generally extremely reliable (unless the lxd snap was upgraded, but I know how to avoid that).  Now, however, I frequently find that it emits this error after a while and then exits:
Error: write unix @->/var/snap/lxd/common/lxd/unix.socket: i/o timeout

This is naturally very frustrating when it happens in the middle of a long task and interrupts it so that I have to start again.  Is there a missing retry loop here or something?
Steps to reproduce
This is quite intermittent and I'm afraid I don't have a reliable reproduction recipe, but it happens to me frequently (multiple times a day) during long lxc exec runs.  Running charmcraft pack in a charm recipe seems a particularly good way to run into it.
Information to attach
The only thing I've been able to observe so far is that the main daemon log says:
t=2022-03-11T13:12:30+0000 lvl=warn msg="Detected poll(POLLNVAL) event."
t=2022-03-11T13:12:30+0000 lvl=warn msg="Detected poll(POLLNVAL) event: exiting."

I found https://discuss.linuxcontainers.org/t/lxd-unix-socket-i-o-timeout/13188 with the same issue, but no response.

@tomponline can you look into this? It's pretty weird that one would hit a timeout on a local LXD.

Yeah, this is just on my laptop.  My laptop is getting on a bit (2014 or so) and often quite busy what with modern web browsers and such, but I normally expect things to retry for a while rather than give up if they hit timeouts.

Yeah it has a retry mechanism in it already, perhaps I'll add some additional debug logging that can be cherry-picked into the latest release so you can enable debug mode and see whats happening.

We've been tightening up the timesouts recently, or rather adding some, as there was a distinct lack of them previously.

I'd be happy to try increasing timeouts to see if that helps, if they're configurable?

I'd be happy to try increasing timeouts to see if that helps, if they're configurable?

They're not at this time, although they are pretty lenient. I'll identify the parts that would be triggering an idle timeout and see if there are problems with it. We've already altered it to not be "time since response" based and be "missed response count" based to account for laptops being put to sleep with exec running.

As the issue appears easy for Colin to reproduce, we should be able to provide a debug binary easily enough.
@tomponline if you prepare a draft PR with extra debugging, I can build a 4.23 binary which matches that of the snap with those changes added on top.

Will do.

OK so looking afresh, I can see that currently lxc exec doesn't actually have any keepalive timeouts on it (its certainly another candidate to have them added though). I added the websocket heartbeats to the events connection, and TCP keepalive & user timeouts to the migration connections.
The only timeout that has been added recently for exec is the connection timeout (which isn't relevant in this case):
https://github.com/lxc/lxd/commit/dc7e09958ffba8aa288b0926aeca9f5dab2c4bdc
I did add a check for the exec control socket closing that would kill the exec session:
https://github.com/lxc/lxd/pull/9750
https://github.com/lxc/lxd/pull/9597
That has some logging in it already though, so if you enable debug logging in LXD (sudo snap set lxd daemon.debug=true; sudo systemctl reload snap.lxd.daemon) then we should be able to see if that is what is triggering.
@stgraber did you say you have a branch that removes/reworks ExecReaderToChannel (which is what is generating Detected poll(POLLNVAL) messages).

Yeah, my ws branch replaces it entirely but currently breaks rsync based migration...
For debugging, note that you can also just run lxc monitor --pretty and will get live debug output this way even if the daemon is running in normal mode.

@cjwatson the events websocket heartbeat is currently 10s with 2 missed "pongs" required, which does also log if it timeouts:
https://github.com/lxc/lxd/blob/34d0d2e0b5c8f3c9f0904adaf8c8609f0fe271c2/lxd/events/common.go#L43-L84

@cjwatson I would be interested to see the debug log output (either from/var/snap/lxd/common/lxd/logs/lxd.log or from  lxc monitor --pretty ) when this next occurs to try and correlate the order that things are happening.

@cjwatson also interesting that the error Error: write unix @->/var/snap/lxd/common/lxd/unix.socket: i/o timeout suggests that the timeout is occurring writing stdin data to the unix socket (rather than it being abruptly closed from the LXD side due to some timeout there). Is the command you are running send lots of data to stdin?

I'm a bit confused by the question - sending data to its own stdin?  I wouldn't expect that to happen much at all, except by accident.  The commands I'm typically running do moderate amounts of interactive I/O, but not particularly enormous amounts - think things like a test suite producing a line of output for each test it runs.  I often see this when I haven't been sending anything to the command's stdin from outside.
Here's the debug log output from a failure I just ran into, making an ephemeral copy of a container and running part of our test suite in the copy; the failure was at 17:15:33.
DBUG[03-11|17:14:06] Handling API request                     ip=@ method=GET protocol=unix url=/1.0 username=cjwatson
DBUG[03-11|17:14:06] Handling API request                     ip=@ method=GET protocol=unix url="/1.0/instances/xenial-lptest-base?recursion=1" username=cjwatson
DBUG[03-11|17:14:06] GetInstanceUsage started                 project=default driver=zfs instance=xenial-lptest-base pool=lxd
DBUG[03-11|17:14:06] GetInstanceUsage finished                pool=lxd project=default driver=zfs instance=xenial-lptest-base
DBUG[03-11|17:14:08] Handling API request                     url=/1.0 username=cjwatson ip=@ method=GET protocol=unix
DBUG[03-11|17:14:08] Handling API request                     username=cjwatson ip=@ method=GET protocol=unix url=/1.0/instances/xenial-lptest-base
DBUG[03-11|17:14:09] Handling API request                     ip=@ method=GET protocol=unix url=/1.0/events username=cjwatson
DBUG[03-11|17:14:09] Event listener server handler started    remote=@ listener=443219a8-30c1-42a3-b0e4-47d73ef39dbf local=/var/snap/lxd/common/lxd/unix.socket
DBUG[03-11|17:14:09] Handling API request                     ip=@ method=POST protocol=unix url=/1.0/instances username=cjwatson
DBUG[03-11|17:14:09] Responding to instance create
DBUG[03-11|17:14:09] Skipping key from copy source            key=volatile.last_state.power project=default sourceInstance=xenial-lptest-base sourceProject=default instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:14:09] Skipping key from copy source            instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 key=volatile.eth0.hwaddr project=default sourceInstance=xenial-lptest-base sourceProject=default
DBUG[03-11|17:14:09] Skipping key from copy source            sourceInstance=xenial-lptest-base sourceProject=default instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 key=volatile.idmap.base project=default
DBUG[03-11|17:14:09] Skipping key from copy source            sourceInstance=xenial-lptest-base sourceProject=default instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 key=volatile.idmap.current project=default
DBUG[03-11|17:14:09] Skipping key from copy source            instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 key=volatile.idmap.next project=default sourceInstance=xenial-lptest-base sourceProject=default
DBUG[03-11|17:14:09] Skipping key from copy source            instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 key=volatile.uuid project=default sourceInstance=xenial-lptest-base sourceProject=default
DBUG[03-11|17:14:09] New task Operation: 5b0dffa9-02df-4031-937a-a85a6db598d4
DBUG[03-11|17:14:09] Started task operation: 5b0dffa9-02df-4031-937a-a85a6db598d4
DBUG[03-11|17:14:09] Handling API request                     ip=@ method=GET protocol=unix url=/1.0/operations/5b0dffa9-02df-4031-937a-a85a6db598d4 username=cjwatson
INFO[03-11|17:14:09] ID: 5b0dffa9-02df-4031-937a-a85a6db598d4, Class: task, Description: Creating instance CreatedAt=2022-03-11T17:14:09+0000 UpdatedAt=2022-03-11T17:14:09+0000 Status=Running StatusCode=Running Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 /1.0/containers/xenial-lptest-base] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 /1.0/instances/xenial-lptest-base]]" Metadata=map[] MayCancel=false Err= Location=none
INFO[03-11|17:14:09] ID: 5b0dffa9-02df-4031-937a-a85a6db598d4, Class: task, Description: Creating instance CreatedAt=2022-03-11T17:14:09+0000 UpdatedAt=2022-03-11T17:14:09+0000 Status=Pending StatusCode=Pending Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 /1.0/containers/xenial-lptest-base] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 /1.0/instances/xenial-lptest-base]]" Metadata=map[] MayCancel=false Err= Location=none
DBUG[03-11|17:14:09] Instance operation lock created          action=create instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 project=default reusable=false
INFO[03-11|17:14:09] Creating container                       instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default ephemeral=true
DBUG[03-11|17:14:09] FillInstanceConfig finished              driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd project=default
DBUG[03-11|17:14:09] FillInstanceConfig started               instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd project=default driver=zfs
INFO[03-11|17:14:09] Action: instance-created, Source: /1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
INFO[03-11|17:14:09] Created container                        ephemeral=true instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default
DBUG[03-11|17:14:09] CreateInstanceFromCopy started           driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd project=default snapshots=true src=xenial-lptest-base
DBUG[03-11|17:14:09] CreateInstanceFromCopy same-pool mode detected pool=lxd project=default snapshots=true src=xenial-lptest-base driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:14:09] Mounted ZFS dataset                      dev=lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd
DBUG[03-11|17:14:09] Unmounted ZFS dataset                    volName=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 dev=lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd
DBUG[03-11|17:14:10] CreateInstanceFromCopy finished          pool=lxd project=default snapshots=true src=xenial-lptest-base driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:14:10] UpdateInstanceBackupFile started         driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd project=default
DBUG[03-11|17:14:10] Mounted ZFS dataset                      dev=lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd
DBUG[03-11|17:14:10] Unmounted ZFS dataset                    dev=lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd volName=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:14:10] UpdateInstanceBackupFile finished        pool=lxd project=default driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:14:10] Instance operation lock finished         err=<nil> instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 project=default reusable=false action=create
DBUG[03-11|17:14:10] Success for task operation: 5b0dffa9-02df-4031-937a-a85a6db598d4
INFO[03-11|17:14:10] ID: 5b0dffa9-02df-4031-937a-a85a6db598d4, Class: task, Description: Creating instance CreatedAt=2022-03-11T17:14:09+0000 UpdatedAt=2022-03-11T17:14:09+0000 Status=Success StatusCode=Success Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 /1.0/containers/xenial-lptest-base] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 /1.0/instances/xenial-lptest-base]]" Metadata=map[] MayCancel=false Err= Location=none
DBUG[03-11|17:14:10] Event listener server handler stopped    local=/var/snap/lxd/common/lxd/unix.socket remote=@ listener=443219a8-30c1-42a3-b0e4-47d73ef39dbf
DBUG[03-11|17:14:10] Handling API request                     ip=@ method=GET protocol=unix url=/1.0 username=cjwatson
DBUG[03-11|17:14:10] Handling API request                     ip=@ method=GET protocol=unix url=/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 username=cjwatson
DBUG[03-11|17:14:10] Handling API request                     ip=@ method=GET protocol=unix url=/1.0/events username=cjwatson
DBUG[03-11|17:14:10] Event listener server handler started    listener=49b38192-03a8-4870-93e2-370b677be40f local=/var/snap/lxd/common/lxd/unix.socket remote=@
DBUG[03-11|17:14:10] Handling API request                     url=/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/state username=cjwatson ip=@ method=PUT protocol=unix
DBUG[03-11|17:14:10] New task Operation: b831adeb-5654-43a5-861d-9f1d29669088
INFO[03-11|17:14:10] ID: b831adeb-5654-43a5-861d-9f1d29669088, Class: task, Description: Starting instance CreatedAt=2022-03-11T17:14:10+0000 UpdatedAt=2022-03-11T17:14:10+0000 Status=Pending StatusCode=Pending Resources=map[instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]] Metadata=map[] MayCancel=false Err= Location=none
DBUG[03-11|17:14:10] Started task operation: b831adeb-5654-43a5-861d-9f1d29669088
INFO[03-11|17:14:10] ID: b831adeb-5654-43a5-861d-9f1d29669088, Class: task, Description: Starting instance CreatedAt=2022-03-11T17:14:10+0000 UpdatedAt=2022-03-11T17:14:10+0000 Status=Running StatusCode=Running Resources=map[instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]] Metadata=map[] MayCancel=false Err= Location=none
DBUG[03-11|17:14:10] Start started                            instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default stateful=false
DBUG[03-11|17:14:10] Instance operation lock created          reusable=false action=start instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 project=default
DBUG[03-11|17:14:10] Handling API request                     protocol=unix url=/1.0/operations/b831adeb-5654-43a5-861d-9f1d29669088 username=cjwatson ip=@ method=GET
DBUG[03-11|17:14:10] MountInstance started                    driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd project=default
DBUG[03-11|17:14:10] Mounted ZFS dataset                      path=/var/snap/lxd/common/lxd/storage-pools/lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd dev=lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 driver=zfs
DBUG[03-11|17:14:10] MountInstance finished                   driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd project=default
DBUG[03-11|17:14:10] Starting device                          project=default type=nic device=eth0 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container
DBUG[03-11|17:14:11] Scheduler: network: vethdf9c5d0d has been added: updating network priorities
DBUG[03-11|17:14:11] Scheduler: network: veth1b7f5c5c has been added: updating network priorities
DBUG[03-11|17:14:11] Starting device                          type=disk device=home instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default
DBUG[03-11|17:14:11] Starting device                          device=root instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default type=disk
INFO[03-11|17:14:11] Starting container                       stateful=false used="1970-01-01 00:00:00 +0000 UTC" action=start created="2022-03-11 17:14:09.381019176 +0000 UTC" ephemeral=true instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default
DBUG[03-11|17:14:11] UpdateInstanceBackupFile started         pool=lxd project=default driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:14:11] Skipping unmount as in use               driver=zfs pool=lxd refCount=1 volName=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:14:11] UpdateInstanceBackupFile finished        driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd project=default
DBUG[03-11|17:14:11] Handling API request                     ip=@ method=GET protocol=unix url="/internal/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/onstart?project=default" username=root
DBUG[03-11|17:14:12] Scheduler: container xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 started: re-balancing
INFO[03-11|17:14:12] Started container                        instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default stateful=false used="1970-01-01 00:00:00 +0000 UTC" action=start created="2022-03-11 17:14:09.381019176 +0000 UTC" ephemeral=true
DBUG[03-11|17:14:12] Instance operation lock finished         project=default reusable=false action=start err=<nil> instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
INFO[03-11|17:14:12] Action: instance-started, Source: /1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0, Requestor: unix/cjwatson (@)
DBUG[03-11|17:14:12] Start finished                           instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default stateful=false
DBUG[03-11|17:14:12] Success for task operation: b831adeb-5654-43a5-861d-9f1d29669088
INFO[03-11|17:14:12] ID: b831adeb-5654-43a5-861d-9f1d29669088, Class: task, Description: Starting instance CreatedAt=2022-03-11T17:14:10+0000 UpdatedAt=2022-03-11T17:14:10+0000 Status=Success StatusCode=Success Resources=map[instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]] Metadata=map[] MayCancel=false Err= Location=none
DBUG[03-11|17:14:12] Event listener server handler stopped    listener=49b38192-03a8-4870-93e2-370b677be40f local=/var/snap/lxd/common/lxd/unix.socket remote=@
DBUG[03-11|17:14:13] Handling API request                     ip=@ method=GET protocol=unix url=/1.0 username=cjwatson
DBUG[03-11|17:14:13] Event listener server handler started    listener=2a06c425-2f5a-4b39-bbf2-d717d38239fa local=/var/snap/lxd/common/lxd/unix.socket remote=@
DBUG[03-11|17:14:13] Handling API request                     ip=@ method=GET protocol=unix url=/1.0/events username=cjwatson
DBUG[03-11|17:14:13] Handling API request                     url=/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/exec username=cjwatson ip=@ method=POST protocol=unix
DBUG[03-11|17:14:13] New websocket Operation: 361d3bfa-cf96-4e08-ad11-5db4876b0db4
INFO[03-11|17:14:13] ID: 361d3bfa-cf96-4e08-ad11-5db4876b0db4, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:13+0000 UpdatedAt=2022-03-11T17:14:13+0000 Status=Pending StatusCode=Pending Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[cloud-init status --wait] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:8cb9807dc1a95e104e4dbcc65c337928d78dfd795c80efb05009900d23cd1391 control:cf6baccdb1ae7d59ad9ce6bd1758ff7e973ba3018b93fa68be887379256b9670] interactive:true]" MayCancel=false Err= Location=none
DBUG[03-11|17:14:13] Waiting for exec websockets to connect
DBUG[03-11|17:14:13] Started websocket operation: 361d3bfa-cf96-4e08-ad11-5db4876b0db4
INFO[03-11|17:14:13] ID: 361d3bfa-cf96-4e08-ad11-5db4876b0db4, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:13+0000 UpdatedAt=2022-03-11T17:14:13+0000 Status=Running StatusCode=Running Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[cloud-init status --wait] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:8cb9807dc1a95e104e4dbcc65c337928d78dfd795c80efb05009900d23cd1391 control:cf6baccdb1ae7d59ad9ce6bd1758ff7e973ba3018b93fa68be887379256b9670] interactive:true]" MayCancel=false Err= Location=none
DBUG[03-11|17:14:13] Connected websocket Operation: 361d3bfa-cf96-4e08-ad11-5db4876b0db4
DBUG[03-11|17:14:13] Handling API request                     url="/1.0/operations/361d3bfa-cf96-4e08-ad11-5db4876b0db4/websocket?secret=cf6baccdb1ae7d59ad9ce6bd1758ff7e973ba3018b93fa68be887379256b9670" username=cjwatson ip=@ method=GET protocol=unix
DBUG[03-11|17:14:13] Handled websocket Operation: 361d3bfa-cf96-4e08-ad11-5db4876b0db4
DBUG[03-11|17:14:13] Connected websocket Operation: 361d3bfa-cf96-4e08-ad11-5db4876b0db4
DBUG[03-11|17:14:13] Handling API request                     protocol=unix url="/1.0/operations/361d3bfa-cf96-4e08-ad11-5db4876b0db4/websocket?secret=8cb9807dc1a95e104e4dbcc65c337928d78dfd795c80efb05009900d23cd1391" username=cjwatson ip=@ method=GET
DBUG[03-11|17:14:13] Handled websocket Operation: 361d3bfa-cf96-4e08-ad11-5db4876b0db4
DBUG[03-11|17:14:13] Handling API request                     ip=@ method=GET protocol=unix url=/1.0/operations/361d3bfa-cf96-4e08-ad11-5db4876b0db4 username=cjwatson
DBUG[03-11|17:14:13] Instance process started                 PID=4122150 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=true project=default
DBUG[03-11|17:14:13] Retrieved PID of executing child process attachedPid=4122150 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default
INFO[03-11|17:14:13] Action: instance-exec, Source: /1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 command="[cloud-init status --wait]"
DBUG[03-11|17:14:13] Exec control handler started             PID=4122150 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=true project=default
DBUG[03-11|17:14:13] Exec mirror websocket started            PID=4122150 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=true number=0 project=default
DBUG[03-11|17:14:27] Success for websocket operation: 361d3bfa-cf96-4e08-ad11-5db4876b0db4
DBUG[03-11|17:14:24] Instance process stopped                 PID=4122150 exitStatus=0 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=true project=default
DBUG[03-11|17:14:25] Exec control handler finished            PID=4122150 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=true project=default
DBUG[03-11|17:14:25] Sending write barrier
DBUG[03-11|17:14:26] DefaultWriter got error getting next reader err="websocket: close 1006 (abnormal closure): unexpected EOF"
INFO[03-11|17:14:27] ID: 361d3bfa-cf96-4e08-ad11-5db4876b0db4, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:13+0000 UpdatedAt=2022-03-11T17:14:26+0000 Status=Running StatusCode=Running Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[cloud-init status --wait] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:8cb9807dc1a95e104e4dbcc65c337928d78dfd795c80efb05009900d23cd1391 control:cf6baccdb1ae7d59ad9ce6bd1758ff7e973ba3018b93fa68be887379256b9670] interactive:true return:0]" MayCancel=false Err= Location=none
INFO[03-11|17:14:27] ID: 361d3bfa-cf96-4e08-ad11-5db4876b0db4, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:13+0000 UpdatedAt=2022-03-11T17:14:26+0000 Status=Success StatusCode=Success Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[cloud-init status --wait] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:8cb9807dc1a95e104e4dbcc65c337928d78dfd795c80efb05009900d23cd1391 control:cf6baccdb1ae7d59ad9ce6bd1758ff7e973ba3018b93fa68be887379256b9670] interactive:true return:0]" MayCancel=false Err= Location=none
DBUG[03-11|17:14:26] Exec mirror websocket finished           interactive=true number=0 project=default PID=4122150 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:14:24] Detected poll(POLLHUP) event: exiting.
DBUG[03-11|17:14:26] Updated metadata for websocket Operation: 361d3bfa-cf96-4e08-ad11-5db4876b0db4
DBUG[03-11|17:14:28] Event listener server handler stopped    listener=2a06c425-2f5a-4b39-bbf2-d717d38239fa local=/var/snap/lxd/common/lxd/unix.socket remote=@
DBUG[03-11|17:14:32] Handling API request                     method=GET protocol=unix url=/1.0 username=cjwatson ip=@
DBUG[03-11|17:14:33] Handling API request                     ip=@ method=GET protocol=unix url=/1.0/events username=cjwatson
DBUG[03-11|17:14:34] Event listener server handler started    local=/var/snap/lxd/common/lxd/unix.socket remote=@ listener=e6b3353f-9490-4636-9ea7-1ab0a3b3aa70
DBUG[03-11|17:14:34] Handling API request                     username=cjwatson ip=@ method=POST protocol=unix url=/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/exec
DBUG[03-11|17:14:34] New websocket Operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
INFO[03-11|17:14:34] ID: 2cdc4758-24cd-4526-930f-d10bba6d8e96, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:34+0000 UpdatedAt=2022-03-11T17:14:34+0000 Status=Pending StatusCode=Pending Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[sed -i /^127\\.0\\.0\\.1/s/$/ xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/ /etc/hosts] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:f2568cd8932094b28e3e936cd94fd0227de8f52b9d375548adb36d5e9462fafc 1:3415adc99673d453382548cd39ff4a9ab0d45c4dcfb71b0703648e405ca66193 2:e79a346bfecc8ecdc17844f668e08d8f589a8a1a861f5736050fb0340a164e77 control:8b10e77c2eda71955d0d8f402f6e42483ceb4251fc76c3df463f0b629b519c60] interactive:false]" MayCancel=false Err= Location=none
INFO[03-11|17:14:34] ID: 2cdc4758-24cd-4526-930f-d10bba6d8e96, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:34+0000 UpdatedAt=2022-03-11T17:14:34+0000 Status=Running StatusCode=Running Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[sed -i /^127\\.0\\.0\\.1/s/$/ xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/ /etc/hosts] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:f2568cd8932094b28e3e936cd94fd0227de8f52b9d375548adb36d5e9462fafc 1:3415adc99673d453382548cd39ff4a9ab0d45c4dcfb71b0703648e405ca66193 2:e79a346bfecc8ecdc17844f668e08d8f589a8a1a861f5736050fb0340a164e77 control:8b10e77c2eda71955d0d8f402f6e42483ceb4251fc76c3df463f0b629b519c60] interactive:false]" MayCancel=false Err= Location=none
DBUG[03-11|17:14:34] Started websocket operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
DBUG[03-11|17:14:34] Handling API request                     username=cjwatson ip=@ method=GET protocol=unix url="/1.0/operations/2cdc4758-24cd-4526-930f-d10bba6d8e96/websocket?secret=8b10e77c2eda71955d0d8f402f6e42483ceb4251fc76c3df463f0b629b519c60"
DBUG[03-11|17:14:34] Handled websocket Operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
DBUG[03-11|17:14:34] Connected websocket Operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
DBUG[03-11|17:14:34] Handling API request                     protocol=unix url="/1.0/operations/2cdc4758-24cd-4526-930f-d10bba6d8e96/websocket?secret=f2568cd8932094b28e3e936cd94fd0227de8f52b9d375548adb36d5e9462fafc" username=cjwatson ip=@ method=GET
DBUG[03-11|17:14:34] Handled websocket Operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
DBUG[03-11|17:14:34] Connected websocket Operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
DBUG[03-11|17:14:34] Handling API request                     ip=@ method=GET protocol=unix url="/1.0/operations/2cdc4758-24cd-4526-930f-d10bba6d8e96/websocket?secret=3415adc99673d453382548cd39ff4a9ab0d45c4dcfb71b0703648e405ca66193" username=cjwatson
DBUG[03-11|17:14:34] Handled websocket Operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
DBUG[03-11|17:14:34] Handling API request                     ip=@ method=GET protocol=unix url="/1.0/operations/2cdc4758-24cd-4526-930f-d10bba6d8e96/websocket?secret=e79a346bfecc8ecdc17844f668e08d8f589a8a1a861f5736050fb0340a164e77" username=cjwatson
DBUG[03-11|17:14:34] Handled websocket Operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
DBUG[03-11|17:14:34] Connected websocket Operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
DBUG[03-11|17:14:34] Connected websocket Operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
DBUG[03-11|17:14:34] Handling API request                     ip=@ method=GET protocol=unix url=/1.0/operations/2cdc4758-24cd-4526-930f-d10bba6d8e96 username=cjwatson
DBUG[03-11|17:14:34] Waiting for exec websockets to connect
INFO[03-11|17:14:34] Action: instance-exec, Source: /1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 command="[sed -i /^127\\.0\\.0\\.1/s/$/ xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/ /etc/hosts]"
DBUG[03-11|17:14:34] Retrieved PID of executing child process attachedPid=4124067 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default
DBUG[03-11|17:14:34] Exec control handler started             instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=false project=default PID=4124067
DBUG[03-11|17:14:34] Instance process started                 PID=4124067 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=false project=default
DBUG[03-11|17:14:34] Exec mirror websocket started            PID=4124067 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=false number=0 project=default
DBUG[03-11|17:14:34] Exec mirror websocket started            project=default PID=4124067 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=false number=1
DBUG[03-11|17:14:34] Exec mirror websocket started            PID=4124067 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=false number=2 project=default
DBUG[03-11|17:14:34] WebsocketRecvStream got message barrier
DBUG[03-11|17:14:34] Exec mirror websocket finished           PID=4124067 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=false number=0 project=default
DBUG[03-11|17:14:34] Instance process stopped                 PID=4124067 exitStatus=0 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=false project=default
DBUG[03-11|17:14:34] Exec control handler finished            PID=4124067 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=false project=default
DBUG[03-11|17:14:34] Updated metadata for websocket Operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
DBUG[03-11|17:14:34] Exec mirror websocket finished           interactive=false number=2 project=default PID=4124067 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:14:34] Exec mirror websocket finished           PID=4124067 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=false number=1 project=default
INFO[03-11|17:14:34] ID: 2cdc4758-24cd-4526-930f-d10bba6d8e96, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:34+0000 UpdatedAt=2022-03-11T17:14:34+0000 Status=Running StatusCode=Running Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[sed -i /^127\\.0\\.0\\.1/s/$/ xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/ /etc/hosts] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:f2568cd8932094b28e3e936cd94fd0227de8f52b9d375548adb36d5e9462fafc 1:3415adc99673d453382548cd39ff4a9ab0d45c4dcfb71b0703648e405ca66193 2:e79a346bfecc8ecdc17844f668e08d8f589a8a1a861f5736050fb0340a164e77 control:8b10e77c2eda71955d0d8f402f6e42483ceb4251fc76c3df463f0b629b519c60] interactive:false return:0]" MayCancel=false Err= Location=none
DBUG[03-11|17:14:34] Success for websocket operation: 2cdc4758-24cd-4526-930f-d10bba6d8e96
DBUG[03-11|17:14:34] Event listener server handler stopped    listener=e6b3353f-9490-4636-9ea7-1ab0a3b3aa70 local=/var/snap/lxd/common/lxd/unix.socket remote=@
INFO[03-11|17:14:34] ID: 2cdc4758-24cd-4526-930f-d10bba6d8e96, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:34+0000 UpdatedAt=2022-03-11T17:14:34+0000 Status=Success StatusCode=Success Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[sed -i /^127\\.0\\.0\\.1/s/$/ xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/ /etc/hosts] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:f2568cd8932094b28e3e936cd94fd0227de8f52b9d375548adb36d5e9462fafc 1:3415adc99673d453382548cd39ff4a9ab0d45c4dcfb71b0703648e405ca66193 2:e79a346bfecc8ecdc17844f668e08d8f589a8a1a861f5736050fb0340a164e77 control:8b10e77c2eda71955d0d8f402f6e42483ceb4251fc76c3df463f0b629b519c60] interactive:false return:0]" MayCancel=false Err= Location=none
DBUG[03-11|17:14:36] Handling API request                     url=/1.0 username=cjwatson ip=@ method=GET protocol=unix
DBUG[03-11|17:14:36] Handling API request                     ip=@ method=GET protocol=unix url=/1.0/events username=cjwatson
DBUG[03-11|17:14:36] Handling API request                     method=POST protocol=unix url=/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/exec username=cjwatson ip=@
DBUG[03-11|17:14:37] Event listener server handler started    listener=960d7102-6da8-44f8-9a31-f7a4e4fe3899 local=/var/snap/lxd/common/lxd/unix.socket remote=@
DBUG[03-11|17:14:37] New websocket Operation: baf98850-5fa5-4f14-a050-982a81ba38d7
INFO[03-11|17:14:37] ID: baf98850-5fa5-4f14-a050-982a81ba38d7, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:37+0000 UpdatedAt=2022-03-11T17:14:37+0000 Status=Pending StatusCode=Pending Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[/home/cjwatson/src/canonical/launchpad/git/oci/utilities/run-as cjwatson env /home/cjwatson/src/canonical/launchpad/git/oci/bin/with-xvfb /home/cjwatson/src/canonical/launchpad/git/oci/bin/test -vvc -t lp.snappy] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:548f76b230a5a9c3cdee35d8424975e2bdf8c54f118f993c0d332e3d93302a88 control:9601c3d2b8fc926b4456c5fab895a72e958d93d6c42bbe192e42e6fa7a1c7897] interactive:true]" MayCancel=false Err= Location=none
DBUG[03-11|17:14:37] Started websocket operation: baf98850-5fa5-4f14-a050-982a81ba38d7
INFO[03-11|17:14:37] ID: baf98850-5fa5-4f14-a050-982a81ba38d7, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:37+0000 UpdatedAt=2022-03-11T17:14:37+0000 Status=Running StatusCode=Running Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[/home/cjwatson/src/canonical/launchpad/git/oci/utilities/run-as cjwatson env /home/cjwatson/src/canonical/launchpad/git/oci/bin/with-xvfb /home/cjwatson/src/canonical/launchpad/git/oci/bin/test -vvc -t lp.snappy] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:548f76b230a5a9c3cdee35d8424975e2bdf8c54f118f993c0d332e3d93302a88 control:9601c3d2b8fc926b4456c5fab895a72e958d93d6c42bbe192e42e6fa7a1c7897] interactive:true]" MayCancel=false Err= Location=none
DBUG[03-11|17:14:37] Handling API request                     ip=@ method=GET protocol=unix url="/1.0/operations/baf98850-5fa5-4f14-a050-982a81ba38d7/websocket?secret=9601c3d2b8fc926b4456c5fab895a72e958d93d6c42bbe192e42e6fa7a1c7897" username=cjwatson
DBUG[03-11|17:14:37] Handled websocket Operation: baf98850-5fa5-4f14-a050-982a81ba38d7
DBUG[03-11|17:14:37] Handling API request                     username=cjwatson ip=@ method=GET protocol=unix url="/1.0/operations/baf98850-5fa5-4f14-a050-982a81ba38d7/websocket?secret=548f76b230a5a9c3cdee35d8424975e2bdf8c54f118f993c0d332e3d93302a88"
DBUG[03-11|17:14:37] Handled websocket Operation: baf98850-5fa5-4f14-a050-982a81ba38d7
DBUG[03-11|17:14:37] Connected websocket Operation: baf98850-5fa5-4f14-a050-982a81ba38d7
DBUG[03-11|17:14:37] Handling API request                     url=/1.0/operations/baf98850-5fa5-4f14-a050-982a81ba38d7 username=cjwatson ip=@ method=GET protocol=unix
DBUG[03-11|17:14:37] Waiting for exec websockets to connect
DBUG[03-11|17:14:37] Connected websocket Operation: baf98850-5fa5-4f14-a050-982a81ba38d7
DBUG[03-11|17:14:37] Exec mirror websocket started            number=0 project=default PID=4124212 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=true
DBUG[03-11|17:14:37] Retrieved PID of executing child process instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default attachedPid=4124212
INFO[03-11|17:14:37] Action: instance-exec, Source: /1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 command="[/home/cjwatson/src/canonical/launchpad/git/oci/utilities/run-as cjwatson env /home/cjwatson/src/canonical/launchpad/git/oci/bin/with-xvfb /home/cjwatson/src/canonical/launchpad/git/oci/bin/test -vvc -t lp.snappy]"
DBUG[03-11|17:14:37] Instance process started                 PID=4124212 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=true project=default
DBUG[03-11|17:14:37] Exec control handler started             PID=4124212 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=true project=default
DBUG[03-11|17:15:33] Failed getting exec control websocket reader, killing command interactive=true project=default PID=4124212 err="websocket: close 1006 (abnormal closure): unexpected EOF" instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:15:33] Event listener server handler stopped    listener=960d7102-6da8-44f8-9a31-f7a4e4fe3899 local=/var/snap/lxd/common/lxd/unix.socket remote=@
DBUG[03-11|17:15:33] Forwarded signal "9" to PID "4124212"
DBUG[03-11|17:15:35] Exec control handler finished            PID=4124212 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=true project=default
DBUG[03-11|17:15:33] DefaultWriter got error getting next reader err="websocket: close 1006 (abnormal closure): unexpected EOF"
DBUG[03-11|17:15:33] Sent SIGKILL signal                      interactive=true project=default PID=4124212 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
WARN[03-11|17:15:46] Detected poll(POLLNVAL) event: exiting.
WARN[03-11|17:15:46] Detected poll(POLLNVAL) event.
DBUG[03-11|17:15:44] Instance process stopped                 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=true project=default PID=4124212 exitStatus=137
DBUG[03-11|17:15:49] Sending write barrier
DBUG[03-11|17:15:49] Got err writing barrier write unix /var/snap/lxd/common/lxd/unix.socket->@: write: broken pipe
DBUG[03-11|17:15:50] Exec mirror websocket finished           PID=4124212 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 interactive=true number=0 project=default
DBUG[03-11|17:15:50] Updated metadata for websocket Operation: baf98850-5fa5-4f14-a050-982a81ba38d7
INFO[03-11|17:15:50] ID: baf98850-5fa5-4f14-a050-982a81ba38d7, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:37+0000 UpdatedAt=2022-03-11T17:15:50+0000 Status=Running StatusCode=Running Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[/home/cjwatson/src/canonical/launchpad/git/oci/utilities/run-as cjwatson env /home/cjwatson/src/canonical/launchpad/git/oci/bin/with-xvfb /home/cjwatson/src/canonical/launchpad/git/oci/bin/test -vvc -t lp.snappy] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:548f76b230a5a9c3cdee35d8424975e2bdf8c54f118f993c0d332e3d93302a88 control:9601c3d2b8fc926b4456c5fab895a72e958d93d6c42bbe192e42e6fa7a1c7897] interactive:true return:137]" MayCancel=false Err= Location=none
DBUG[03-11|17:15:50] Success for websocket operation: baf98850-5fa5-4f14-a050-982a81ba38d7
INFO[03-11|17:15:51] ID: baf98850-5fa5-4f14-a050-982a81ba38d7, Class: websocket, Description: Executing command CreatedAt=2022-03-11T17:14:37+0000 UpdatedAt=2022-03-11T17:15:50+0000 Status=Success StatusCode=Success Resources="map[containers:[/1.0/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0] instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]]" Metadata="map[command:[/home/cjwatson/src/canonical/launchpad/git/oci/utilities/run-as cjwatson env /home/cjwatson/src/canonical/launchpad/git/oci/bin/with-xvfb /home/cjwatson/src/canonical/launchpad/git/oci/bin/test -vvc -t lp.snappy] environment:map[HOME:/root LANG:C.UTF-8 PATH:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin TERM:putty-256color USER:root] fds:map[0:548f76b230a5a9c3cdee35d8424975e2bdf8c54f118f993c0d332e3d93302a88 control:9601c3d2b8fc926b4456c5fab895a72e958d93d6c42bbe192e42e6fa7a1c7897] interactive:true return:137]" MayCancel=false Err= Location=none
DBUG[03-11|17:15:52] Handling API request                     url=/1.0 username=cjwatson ip=@ method=GET protocol=unix
DBUG[03-11|17:15:52] Handling API request                     username=cjwatson ip=@ method=GET protocol=unix url=/1.0
DBUG[03-11|17:15:52] Handling API request                     method=GET protocol=unix url=/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 username=cjwatson ip=@
DBUG[03-11|17:15:52] Handling API request                     ip=@ method=GET protocol=unix url="/1.0/instances?recursion=1" username=cjwatson
DBUG[03-11|17:15:53] Handling API request                     ip=@ method=GET protocol=unix url=/1.0/events username=cjwatson
DBUG[03-11|17:15:53] Event listener server handler started    remote=@ listener=05ef5f63-53f4-436a-974c-9ca659458afe local=/var/snap/lxd/common/lxd/unix.socket
DBUG[03-11|17:15:53] Handling API request                     ip=@ method=PUT protocol=unix url=/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/state username=cjwatson
DBUG[03-11|17:15:53] New task Operation: 99d3babc-623a-4415-9113-896d63abbfa6
INFO[03-11|17:15:53] ID: 99d3babc-623a-4415-9113-896d63abbfa6, Class: task, Description: Stopping instance CreatedAt=2022-03-11T17:15:53+0000 UpdatedAt=2022-03-11T17:15:53+0000 Status=Pending StatusCode=Pending Resources=map[instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]] Metadata=map[] MayCancel=false Err= Location=none
DBUG[03-11|17:15:53] Started task operation: 99d3babc-623a-4415-9113-896d63abbfa6
DBUG[03-11|17:15:53] Stop started                             instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default stateful=false
DBUG[03-11|17:15:53] Instance operation lock created          action=stop instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 project=default reusable=false
INFO[03-11|17:15:53] Stopping container                       ephemeral=true instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default stateful=false used="2022-03-11 17:14:12.438677554 +0000 UTC" action=stop created="2022-03-11 17:14:09.381019176 +0000 UTC"
INFO[03-11|17:15:53] ID: 99d3babc-623a-4415-9113-896d63abbfa6, Class: task, Description: Stopping instance CreatedAt=2022-03-11T17:15:53+0000 UpdatedAt=2022-03-11T17:15:53+0000 Status=Running StatusCode=Running Resources=map[instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]] Metadata=map[] MayCancel=false Err= Location=none
DBUG[03-11|17:15:53] Handling API request                     username=cjwatson ip=@ method=GET protocol=unix url=/1.0/instances/focal-buildd/state
DBUG[03-11|17:15:53] Handling API request                     ip=@ method=GET protocol=unix url=/1.0/operations/99d3babc-623a-4415-9113-896d63abbfa6 username=cjwatson
DBUG[03-11|17:15:53] MountInstance started                    driver=zfs instance=focal-buildd pool=lxd project=default
DBUG[03-11|17:15:53] Scheduler: network: eth0 has been added: updating network priorities
DBUG[03-11|17:15:54] MountInstance finished                   pool=lxd project=default driver=zfs instance=focal-buildd
DBUG[03-11|17:15:54] UnmountInstance started                  pool=lxd project=default driver=zfs instance=focal-buildd
DBUG[03-11|17:15:54] Skipping unmount as in use               driver=zfs pool=lxd refCount=1 volName=focal-buildd
DBUG[03-11|17:15:54] UnmountInstance finished                 driver=zfs instance=focal-buildd pool=lxd project=default
DBUG[03-11|17:15:54] Connecting to a VM agent over a VM socket
DBUG[03-11|17:15:54] Sending request to LXD                   etag= method=GET url=https://custom.socket/1.0
DBUG[03-11|17:15:55] Handling API request                     ip=@ method=GET protocol=unix url="/internal/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/onstopns?netns=%2Fproc%2F4121973%2Ffd%2F4&project=default&target=stop" username=root
DBUG[03-11|17:15:55] Stopping device                          project=default type=nic device=eth0 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container
DBUG[03-11|17:15:55] Got response struct from LXD
DBUG[03-11|17:15:55] Sending request to LXD                   etag= method=GET url=https://custom.socket/1.0/state
DBUG[03-11|17:15:55]
        {
                "config": null,
                "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",
                        "network_state_ovn",
                        "storage_volume_api_filtering",
                        "image_restrictions",
                        "storage_zfs_export",
                        "network_dns_records",
                        "storage_zfs_reserve_space",
                        "network_acl_log",
                        "storage_zfs_blocksize",
                        "metrics_cpu_seconds",
                        "instance_snapshot_never",
                        "certificate_token"
                ],
                "api_status": "stable",
                "api_version": "1.0",
                "auth": "trusted",
                "public": false,
                "auth_methods": [
                        "tls"
                ],
                "environment": {
                        "addresses": null,
                        "architectures": null,
                        "certificate": "",
                        "certificate_fingerprint": "",
                        "driver": "",
                        "driver_version": "",
                        "firewall": "",
                        "kernel": "Linux",
                        "kernel_architecture": "x86_64",
                        "kernel_features": null,
                        "kernel_version": "5.4.0-1058-kvm",
                        "lxc_features": null,
                        "os_name": "",
                        "os_version": "",
                        "project": "",
                        "server": "lxd-agent",
                        "server_clustered": false,
                        "server_name": "focal-buildd",
                        "server_pid": 485,
                        "server_version": "4.23",
                        "storage": "",
                        "storage_version": "",
                        "storage_supported_drivers": null
                }
        }
DBUG[03-11|17:15:55]
        {
                "status": "",
                "status_code": 0,
                "disk": null,
                "memory": {
                        "usage": 571609088,
                        "usage_peak": 766955520,
                        "swap_usage": 0,
                        "swap_usage_peak": 0
                },
                "network": {
                        "enp5s0": {
                                "addresses": [
                                        {
                                                "family": "inet",
                                                "address": "10.36.63.24",
                                                "netmask": "24",
                                                "scope": "global"
                                        },
                                        {
                                                "family": "inet6",
                                                "address": "fe80::216:3eff:fe98:c145",
                                                "netmask": "64",
                                                "scope": "link"
                                        }
                                ],
                                "counters": {
                                        "bytes_received": 24647939,
                                        "bytes_sent": 308298,
                                        "packets_received": 41247,
                                        "packets_sent": 3672,
                                        "errors_received": 0,
                                        "errors_sent": 0,
                                        "packets_dropped_outbound": 0,
                                        "packets_dropped_inbound": 0
                                },
                                "hwaddr": "00:16:3e:98:c1:45",
                                "host_name": "",
                                "mtu": 1500,
                                "state": "up",
                                "type": "broadcast"
                        },
                        "lo": {
                                "addresses": [
                                        {
                                                "family": "inet",
                                                "address": "127.0.0.1",
                                                "netmask": "8",
                                                "scope": "local"
                                        },
                                        {
                                                "family": "inet6",
                                                "address": "::1",
                                                "netmask": "128",
                                                "scope": "local"
                                        }
                                ],
                                "counters": {
                                        "bytes_received": 9964,
                                        "bytes_sent": 9964,
                                        "packets_received": 124,
                                        "packets_sent": 124,
                                        "errors_received": 0,
                                        "errors_sent": 0,
                                        "packets_dropped_outbound": 0,
                                        "packets_dropped_inbound": 0
                                },
                                "hwaddr": "",
                                "host_name": "",
                                "mtu": 65536,
                                "state": "up",
                                "type": "loopback"
                        }
                },
                "pid": 1,
                "processes": 24,
                "cpu": {
                        "usage": 113133408469
                }
        }
DBUG[03-11|17:15:55] Got response struct from LXD
DBUG[03-11|17:15:55] GetInstanceUsage started                 project=default driver=zfs instance=focal-buildd pool=lxd
DBUG[03-11|17:15:55] GetInstanceUsage finished                project=default driver=zfs instance=focal-buildd pool=lxd
DBUG[03-11|17:15:55] Clearing instance firewall static filters ipv4=0.0.0.0 ipv6=:: parent=lxdbr0 project=default dev=eth0 host_name=veth1b7f5c5c hwaddr=00:16:3e:93:fa:85 instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:15:56] Handling API request                     ip=@ method=GET protocol=unix url="/internal/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0/onstop?project=default&target=stop" username=root
DBUG[03-11|17:15:56] Container stopped, cleaning up           instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default
DBUG[03-11|17:15:56] Stopping device                          type=disk device=home instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default
DBUG[03-11|17:15:56] Stopping device                          type=disk device=root instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default
DBUG[03-11|17:15:56] UnmountInstance started                  project=default driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd
DBUG[03-11|17:15:56] Unmounted ZFS dataset                    path=/var/snap/lxd/common/lxd/storage-pools/lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd volName=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 dev=lxd/containers/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 driver=zfs
DBUG[03-11|17:15:56] UnmountInstance finished                 driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd project=default
DBUG[03-11|17:15:56] Scheduler: container xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 stopped: re-balancing
INFO[03-11|17:15:56] Deleting container                       instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default used="2022-03-11 17:14:12.438677554 +0000 UTC" created="2022-03-11 17:14:09.381019176 +0000 UTC" ephemeral=true
DBUG[03-11|17:15:56] DeleteInstance started                   driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd project=default
DBUG[03-11|17:15:56] Deleting instance volume                 driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd project=default volName=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:15:57] DeleteInstance finished                  driver=zfs instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 pool=lxd project=default
DBUG[03-11|17:15:57] Success for task operation: 99d3babc-623a-4415-9113-896d63abbfa6
INFO[03-11|17:15:57] Deleted container                        instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default used="2022-03-11 17:14:12.438677554 +0000 UTC" created="2022-03-11 17:14:09.381019176 +0000 UTC" ephemeral=true
INFO[03-11|17:15:57] Action: instance-deleted, Source: /1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
DBUG[03-11|17:15:57] Instance operation lock finished         project=default reusable=false action=stop err=<nil> instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0
INFO[03-11|17:15:57] Action: instance-stopped, Source: /1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0, Requestor: unix/cjwatson (@)
DBUG[03-11|17:15:57] Stop finished                            instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0 instanceType=container project=default stateful=false
INFO[03-11|17:15:57] ID: 99d3babc-623a-4415-9113-896d63abbfa6, Class: task, Description: Stopping instance CreatedAt=2022-03-11T17:15:53+0000 UpdatedAt=2022-03-11T17:15:53+0000 Status=Success StatusCode=Success Resources=map[instances:[/1.0/instances/xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0]] Metadata=map[] MayCancel=false Err= Location=none
DBUG[03-11|17:15:57] Event listener server handler stopped    listener=05ef5f63-53f4-436a-974c-9ca659458afe local=/var/snap/lxd/common/lxd/unix.socket remote=@

Also, I can't completely swear to this, but I'm fairly sure the test command was producing output up to very shortly before it was killed; it didn't look like there was a long timeout first or anything.

Perfect thanks @cjwatson , there's the problem:
DBUG[03-11|17:15:33] Failed getting exec control websocket reader, killing command interactive=true project=default PID=4124212 err="websocket: close 1006 (abnormal closure): unexpected EOF" instance=xenial-lptest-596f3e10-6577-4d71-aa34-4b9527c4ecc0

Which then triggers LXD to disconnect and kill the process:
DBUG[03-11|17:15:33] Event listener server handler stopped    listener=960d7102-6da8-44f8-9a31-f7a4e4fe3899 local=/var/snap/lxd/common/lxd/unix.socket remote=@
DBUG[03-11|17:15:33] Forwarded signal "9" to PID "4124212"

Now until recently the control socket closing did not trigger the process to end.
This was introduced with:
https://github.com/lxc/lxd/pull/9750

The question is why is the control socket from the client getting closed.

Actually that PR https://github.com/lxc/lxd/pull/9750 didn't change the act of kill the process if the control socket disconnected, so thats not the change.
Looks like a while back it ignored every error except specific ones:
https://github.com/lxc/lxd/commit/09edf92612c94b49d735b7c6b6b47ab83b352623

@cjwatson do your CTs use a lot of disk space and/or disk IO? I have the same issue, on Focal 20.04, dir driver over a Ubuntu running on LVM.
@tomponline if you need me to run any tests just ping me.

@cjwatson do your CTs use a lot of disk space and/or disk IO? I have the same issue, on Focal 20.04, dir driver over a Ubuntu running on LVM.

I'm using ZFS, as I think was visible in my config dump above.  Certainly a fair bit of space used (~70G at the moment), but the ZFS pool isn't in the area where it's dangerously close to full so starts going hideously slowly.

guess we can rule out the driver being the culprit. but my CTs are heavy on read/writes and run in the 70s to the low hundreds of GBs.

@cjwatson can I confirm what version of the lxc comand you're using? lxc --version?

@cjwatson also if you add a local TCP remote such as lxc remote add localtcp 127.0.0.1 (you might need to configure LXD to listen on that port lxc config set core.https_address 127.0.0.1:8443 first) and then run it over that do you see the same issues?
lxc exec localtcp:c1 --

I suppose if you can capture (the ableit encrypted) TCP stream tcpdump -i lo port <control port of exec session> then we can 100% confirm that the client is closing the control connection. Then we need to figure out why.

@cjwatson any luck?

We also run into this issue occasionally on our Teamcity CI/CD pipeline. It started right after we upgraded to LXD 5.0.
We see occasional random:
Error: write unix @->/var/snap/lxd/common/lxd/unix.socket: i/o timeout
during lxc exec. This typically happens for commands that take long (order of magnitude multiple hours) to complete.

I ran across this problem when compiling OpenGeoSys with CMake and Ninja in a Ubuntu Jammy (22.04) container hosted by my home LXC cluster comosed of 3 Thinkpad T430 laptops, which have an i7 2-core overthreaded CPU (4 logical CPUs) and 8 GB mem each. However, this has never occurred in my production LXC cluster composed of 4 IBM X3650 M3 servers in my institute datacenter. Therefore, I believe it's not the fault of LXC, but the problem must hide in C/C++ compiling with CMake and Ninja.
In order to see the error messages, I enabled the SSH server in the cotainer (sudo apt-get install -y openssh-server). Then I remotely logged in the container with command ssh on Linux (or PuTTy on Windows) instead of using  lxc exec container_name -- su - ubuntu --login. Compiling with Ninja again, I saw the Unity-Build failure info appear after some while.

Hi,
not to being a drag, but Is there any ETA on the keepalives during lxc exec? I'm getting bitten pretty hard by this as I have a proxy between me and lxd that is pretty harsh on killing idle connections.
The status says 'Incomplete', what do you need to be able to start working on this? I can provide TCP dumps where it is pretty obvious what is to blame here.
many thanks

We still need a reproducer for this as we've not been able to reproduce the issue.
Does this only occur when using TCP socket?

Yes that would be useful see https://github.com/lxc/lxd/issues/10034#issuecomment-1074230589

On Wed, Apr 27, 2022 at 02:25:07AM -0700, Tom Parrott wrote:

@cjwatson are you still experiencing this with LXD 5.0?

With 5.0.0-b0287c1 (snap revision 22923), I kicked off a full Launchpad
test run last night and it hit the same I/O timeout symptom as before
after about an hour and a half, so yes.
I haven't had a chance to capture tcpdump information yet, but haven't
forgotten ...
--
Colin Watson (he/him)                              @.***

While looking some more, I actually realized that no matter what I do with my lxc exec the connection will always get killed exactly at the timeout. I've noticed 5 connections for each lxc exec in the tcp dump, could it be that lxc client opens 6 connections for each lxc exec and then keeps one or more of them idle (control connection?) so when that one gets killed everything gets killed?
in one shell:
~$  https_proxy= lxc exec lxd:v id
uid=0(root) gid=0(root) groups=0(root)
in another:
~$ sudo tcpdump -n "tcp[tcpflags] & tcp-syn != 0 and port 8443"
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), snapshot length 262144 bytes
08:41:39.924028 IP 192.168.221.182.53010 > 192.168.220.135.8443: Flags [S], seq 903777157, win 65520, options [mss 1456,sackOK,TS val 4199857669 ecr 0,nop,wscale 7], length 0
08:41:39.924145 IP 192.168.220.135.8443 > 192.168.221.182.53010: Flags [S.], seq 3689853196, ack 903777158, win 28880, options [mss 1456,nop,nop,TS val 4083228311 ecr 4199857669,nop,wscale 7], length 0
08:41:39.951584 IP 192.168.221.182.53026 > 192.168.220.135.8443: Flags [S], seq 1100666107, win 65520, options [mss 1456,sackOK,TS val 4199857697 ecr 0,nop,wscale 7], length 0
08:41:39.951831 IP 192.168.220.135.8443 > 192.168.221.182.53026: Flags [S.], seq 524795072, ack 1100666108, win 28880, options [mss 1456,nop,nop,TS val 4083228339 ecr 4199857697,nop,wscale 7], length 0
08:41:39.974212 IP 192.168.221.182.53028 > 192.168.220.135.8443: Flags [S], seq 3307833956, win 65520, options [mss 1456,sackOK,TS val 4199857719 ecr 0,nop,wscale 7], length 0
08:41:39.974291 IP 192.168.220.135.8443 > 192.168.221.182.53028: Flags [S.], seq 4032278395, ack 3307833957, win 28880, options [mss 1456,nop,nop,TS val 4083228361 ecr 4199857719,nop,wscale 7], length 0
08:41:40.027178 IP 192.168.221.182.53032 > 192.168.220.135.8443: Flags [S], seq 60756902, win 65520, options [mss 1456,sackOK,TS val 4199857772 ecr 0,nop,wscale 7], length 0
08:41:40.027263 IP 192.168.220.135.8443 > 192.168.221.182.53032: Flags [S.], seq 2869073587, ack 60756903, win 28880, options [mss 1456,nop,nop,TS val 4083228414 ecr 4199857772,nop,wscale 7], length 0
08:41:40.066206 IP 192.168.221.182.53042 > 192.168.220.135.8443: Flags [S], seq 3349162246, win 65520, options [mss 1456,sackOK,TS val 4199857811 ecr 0,nop,wscale 7], length 0
08:41:40.066326 IP 192.168.220.135.8443 > 192.168.221.182.53042: Flags [S.], seq 3186268849, ack 3349162247, win 28880, options [mss 1456,nop,nop,TS val 4083228453 ecr 4199857811,nop,wscale 7], length 0
08:41:40.104865 IP 192.168.221.182.53048 > 192.168.220.135.8443: Flags [S], seq 3596536357, win 65520, options [mss 1456,sackOK,TS val 4199857850 ecr 0,nop,wscale 7], length 0
08:41:40.104990 IP 192.168.220.135.8443 > 192.168.221.182.53048: Flags [S.], seq 1568404081, ack 3596536358, win 28880, options [mss 1456,nop,nop,TS val 4083228492 ecr 4199857850,nop,wscale 7], length 0

I've noticed 5 connections for each lxc exec in the tcp dump, could it be that lxc client opens 6 connections for each lxc exec and then keeps one or more of them idle (control connection?) so when that one gets killed everything gets killed?

In non-interactive mode I would expect the 5 connections:

Control
Operation
Stdin
Stdout
Stderr

And for interactive sessions would expect the 3 connections:

Control
Operation
Bidirectional terminal

And yes when the control channel is disconnected all connections and the remote command are killed.

Yeah, so that's probably it, at least in my case.
Any chance of sending some keepalives on the control connection, or any other that is kept idle?

Yeah, so that's probably it, at least in my case.
Any chance of sending some keepalives on the control connection, or any other that is kept idle?

I'll take a look at adding this.

Can you use sudo ss -tnpo to show if the connections to LXD have the keepalive timers at TCP level enabled, as it seems they do for me, e.g.
These are the 3 connections for an active interactive session. You can see the keepalive,... timer stats on each connection.
sudo ss -tnpo | grep lxc
ESTAB 0      0                                  127.0.0.1:44330                    127.0.0.1:8442  users:(("lxc",pid=11404,fd=3)) timer:(keepalive,3.192ms,0)
ESTAB 0      0                                  127.0.0.1:44350                    127.0.0.1:8442  users:(("lxc",pid=11404,fd=7)) timer:(keepalive,13sec,0)
ESTAB 0      0                                  127.0.0.1:44358                    127.0.0.1:8442  users:(("lxc",pid=11404,fd=8)) timer:(keepalive,13sec,0)

Does your firewall kill connections and ignores the TCP level keepalive?

Ah, you're using a proxy, so its likely one side of the connection isn't using TCP keepalives.

in one shell:
~$ https_proxy= lxc exec lxd:v id
uid=0(root) gid=0(root) groups=0(root)

In this example are you still using the proxy?

What I am doing to reproduce, I start haproxy with the following config file
~$ cat /tmp/haproxy.cfg
listen 127.0.0.1:8443
bind 127.0.0.1:8443
mode tcp
timeout connect 5000ms
timeout client 20000ms
timeout server 20000ms
timeout tunnel 20000ms
option tcpka
option clitcpka
option srvtcpka

server lxd 192.168.220.135:8443

then in /etc/hosts i put
~$ fgrep lxd /etc/hosts
127.0.0.1       localhost lxd

so everything goes over localhost to haproxy and then to my lxd cluster at 192.168.220.135
during the exec, i loop through a shell loop to generate consistent traffic

~$ https_proxy= lxc exec v -- bash -c 'for i in $(seq 0 1000); do echo $i; sleep 1; done'
0
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19

and here it dies every time
during those 20 secs keepalive timers are there and low on the client side but high on the server side, I really don't know how to interpret this

~$  sudo ss -tnpo | egrep 'lxc|haproxy'
ESTAB 0      0            127.0.0.1:34890       127.0.0.1:8443  users:(("lxc",pid=93037,fd=3)) timer:(keepalive,692ms,0)
ESTAB 0      0            127.0.0.1:8443        127.0.0.1:34914 users:(("haproxy",pid=92668,fd=18)) timer:(keepalive,119min,0)
ESTAB 0      0            127.0.0.1:8443        127.0.0.1:34890 users:(("haproxy",pid=92668,fd=16)) timer:(keepalive,119min,0)
ESTAB 0      0      192.168.221.182:56826 192.168.220.135:8443  users:(("haproxy",pid=92668,fd=17)) timer:(keepalive,119min,0)
ESTAB 0      0            127.0.0.1:34928       127.0.0.1:8443  users:(("lxc",pid=93037,fd=8)) timer:(keepalive,584ms,0)
ESTAB 0      0            127.0.0.1:34914       127.0.0.1:8443  users:(("lxc",pid=93037,fd=7)) timer:(keepalive,1.972ms,0)
ESTAB 0      0      192.168.221.182:56870 192.168.220.135:8443  users:(("haproxy",pid=92668,fd=21)) timer:(keepalive,119min,0)
ESTAB 0      0            127.0.0.1:8443        127.0.0.1:34928 users:(("haproxy",pid=92668,fd=20)) timer:(keepalive,119min,0)
ESTAB 0      0      192.168.221.182:56856 192.168.220.135:8443  users:(("haproxy",pid=92668,fd=19)) timer:(keepalive,119min,0)
~$  sudo ss -tnpo | egrep 'lxc|haproxy'
ESTAB 0      0            127.0.0.1:34890       127.0.0.1:8443  users:(("lxc",pid=93037,fd=3)) timer:(keepalive,1.704ms,0)
ESTAB 0      0            127.0.0.1:8443        127.0.0.1:34914 users:(("haproxy",pid=92668,fd=18)) timer:(keepalive,119min,0)
ESTAB 0      0            127.0.0.1:8443        127.0.0.1:34890 users:(("haproxy",pid=92668,fd=16)) timer:(keepalive,119min,0)
ESTAB 0      0      192.168.221.182:56826 192.168.220.135:8443  users:(("haproxy",pid=92668,fd=17)) timer:(keepalive,119min,0)
ESTAB 0      0            127.0.0.1:34928       127.0.0.1:8443  users:(("lxc",pid=93037,fd=8)) timer:(keepalive,2.376ms,0)
ESTAB 0      0            127.0.0.1:34914       127.0.0.1:8443  users:(("lxc",pid=93037,fd=7)) timer:(keepalive,760ms,0)
ESTAB 0      0      192.168.221.182:56870 192.168.220.135:8443  users:(("haproxy",pid=92668,fd=21)) timer:(keepalive,119min,0)
ESTAB 0      0            127.0.0.1:8443        127.0.0.1:34928 users:(("haproxy",pid=92668,fd=20)) timer:(keepalive,119min,0)
ESTAB 0      0      192.168.221.182:56856 192.168.220.135:8443  users:(("haproxy",pid=92668,fd=19)) timer:(keepalive,119min,0)

@aivanise thanks for your reproducer, I used it to produce a fix:
https://github.com/lxc/lxd/pull/11011

many thanks!

@cjwatson the PR that closed this issue added both TCP keepalives and websocket level keepalives. Although IIRC you were experiencing disconnects when using the UNIX socket, so the TCP keepalives won't help. However the websocket ones may do.
If you continue to experience issues with LXD 5.7 then we can reopen the issue. Thanks

If you continue to experience issues with LXD 5.7 then we can reopen the issue. Thanks

Do I have to upgrade both server and client for this to work or is the client enough? If the latter, I guess latest nightly should already work, correct?

If you continue to experience issues with LXD 5.7 then we can reopen the issue. Thanks

I'm also facing this problem on local installations. After upgrading to LXD 5.7 yesterday on an ODROID N2+ (arm64/aarch64) and trying to build gcc 11.3 (using pbuilder/debbuild, which is a torture test for this machine), I still see Error: websocket: close 1006 (abnormal closure): unexpected EOF after a couple of hours; the log shows the following:
time="2022-10-25T06:18:36+02:00" level=warning msg="Failed getting exec control websocket reader, killing command" PID=1884240 err="read unix /var/snap/lxd/common/lxd/unix.socket->@: read: connection reset by peer" instance=pbuilder-arm64 interactive=true project="{{map[features.images:true features.networks:true features.profiles:true features.storage.buckets:true features.storage.volumes:true] Default LXD project} default []}"
time="2022-10-25T06:18:40+02:00" level=warning msg="Detected poll(POLLNVAL) event: exiting"
time="2022-10-25T06:18:42+02:00" level=warning msg="Transaction timed out. Retrying once" err="Failed to begin transaction: context deadline exceeded" member=1
time="2022-10-25T06:18:42+02:00" level=warning msg="Transaction timed out. Retrying once" err="Failed to begin transaction: context deadline exceeded" member=1
time="2022-10-25T06:18:42+02:00" level=warning msg="Failed to rollback transaction after error (Failed loading instance profiles: Failed to fetch from \"profile_config\" table: sql: Rows are closed): sql: transaction has already been committed or rolled back"

For the record, using previous LXD versions, I also saw the above error on different hosts/architectures without any load (according to the byobu status line at that time) after a certain period of time. Time will show whether this has been addressed by #11011 ...

Please can you provide full reproducer steps so we can try to reproduce this. It maybe that the particular machine is too heavily loaded to keep up with kee alive responses in a timely manner.

As suggested by @tomponline, I reran the above using lxc --debug exec --user 1000 localtcp:pbuilder-arm64. The captured logs are attached (shortened as much as I deemed to be safe).
lxd_websocket_error02.zip

Hi there, I've hit the same problem on gentoo with lxc-5.0.1

Thanks for the update. LXD 5.7 and LXD 5.8 had some keepalive and timeout improvements which should help.
These will be included in the soon to be released LXD 5.0.2

I still have this problem with LXD 5.8 in the following environment: NixOS host -> libvirt-lxc Arch Linux container -> lxd from snap installed by snapcraft (which itself is also installed from snap)

Do you get it if you don't stress your system as much doing the make command, perhaps using fewer concurrent jobs with the -j flag?

I wonder whether it's possible to override job count at all... I have only craftctl default in the snapcraft.yaml, snapcraft chooses build command automagically...

The system remains responsible, by the way

Does this happen 100% of the time? And is it a nested container effectively?

What we've not been able to ascertain is what can causing a write timeout on a unix socket when there isn't one explicitly set.

How long does it say on that make -j 32 command before it fails?

Does this happen 100% of the time?

Yes. It builds only around a minute and times out. It first happened when building other part, but that other part was a small library and built successfully on next run. OpenSSL is not small though, so I can't get through its build step.

And is it a nested container effectively?

Yes. NixOS doesn't provide snapcraft nor snap, so I have to run a container with another distro to get snapcraft.

Can you try it on a different machine to see if its reliably reproducible or dependent on machine?
I've tried creating high load on my system and never seen this occur once. Which is why its been so hard to diagnose.

Ok, it just failed, it doesn't inherit the variable, maybe it doesn't pass through it to the snapcraft instance in the container...

It's a broken pipe this time though: Error: write unix @->/var/snap/lxd/common/lxd/unix.socket: write: broken pipe
The error in systemctl seem to be the same though:
Nov 24 16:03:42 archlinux lxd.daemon[391]: time="2022-11-24T16:03:42Z" level=warning msg="Failed getting exec control websocket reader, killing command" PID=1518 err="read unix /var/snap/lxd/common/lxd/unix.socket->@: read: connection reset by peer" instance=snapcraft-telegram-desktop-on-amd64-for-amd64-14811284 interactive=true project="{{map[features.images:true features.profiles:true features.storage.buckets:true features.storage.volumes:true] } snapcraft []}"
Nov 24 16:03:42 archlinux lxd.daemon[391]: time="2022-11-24T16:03:42Z" level=warning msg="Detected poll(POLLNVAL) event: exiting"

This seem to happen only with lxd inside libvirt-lxc. This doesn't happen with lxd inside the common lxc.

I have upgraded to 5.7 and this does not seem to be fixed. Is there some more/different work done on this in 5.8 as opposed to 5.7 or shall I reopen right now?

Only LXD 5.8 is supported so you'll need to confirm its an issue on that anyway. But I believe there were changes on this in LXD 5.8 too. We'll need reproducer steps (and if needed an export of the affected instance we can use if it needs some particular setup). Thanks

and later LXD itself being killed on the host due to OOM after the VM guest's memory was increased to almost the total size of the host's memory

If this was the case I would see this in systemd logs, but I don't see any lines in systemd logs about stopping/starting lxd service

The problem is we don't have a reproducer sadly :(

Have you tried to run lxd inside a libvirt-lxc (exactly libvirt one) container?

I would need to see some step by step guides or a precreated image to use for that?

Well, install snapcraft and try to build telegram-desktop snap, that's what I'm trying to do. Personally I use Arch Linux image.

Can you give me step by step reproducer steps please to avoid any wasted time and using the wrong config compared to your reproducer? Thanks

Starting from lxc launch ... for a new instance would be great :)

Looks like I already removed my libvirt-lxc config and, well, I don't care about this anymore, the non-libvirt lxc seem to be much faster and I think it's like second time libvirt-lxc does a bad thing for me, maybe I should forget it exists.

I run Nextcloud official Docker containers inside LXD containers all on btrfs. Because of some performance issues I did a Google search and came across this link:
https://discuss.linuxcontainers.org/t/run-docker-on-lxd-container/11575/3
@stgraber mentions this:
Still in the unprivileged case, you’d also want to set security.syscalls.intercept.mknod=true and security.syscalls.intercept.setxattr=true to avoid some issues unpacking some Docker layers.
I already had security.nesting set as true.
The result of the above "security.syscalls.intercept.mknod=true"  "security.syscalls.intercept.setxattr=true" gets me this error message:
"Error: write unix @->/var/snap/lxd/common/lxd/unix.socket: i/o timeout"
and I get thrown out of the container when I run "docker-compose pull" after sudo lxc exec dockercontainer -- /bin/bash
It's fixed after I set "security.syscalls.intercept.mknod=false"  "security.syscalls.intercept.setxattr=false" and everything is running smoothly again.
Hope this helps.

What LXD version and kernel is that?
Can you also look at journalctl -u snap.lxd.daemon -n 300 for any sign of a crash?

What LXD version and kernel is that? Can you also look at journalctl -u snap.lxd.daemon -n 300 for any sign of a crash?

messages:
lxd.daemon[45575]: time="2023-04-19T11:13:32+02:00" level=warning msg="Failed getting exec control websocket reader, killing command" PID=75967 err="read unix /var/snap/lxd/common/lxd/unix.socket->@: read: connection reset by peer" instance=itknext interactive=true project=default
and
lxd.daemon[45575]: time="2023-04-19T11:13:32+02:00" level=warning msg="Detected poll(POLLNVAL) event: exiting"

Ubuntu Jammy kernel 5.15.0-69-generic
lxd snap latest/stable:    5.13-cea5ee2

🤞

I experienced write unix @->/var/snap/lxd/common/lxd/unix.socket: i/o timeout under heavy load for 5.12 and 5.13
Just tested 5.14 and it seems fixed, no more unix.socket i/o timeout even under heavy load!

@nteodosio what version of lxd is that running?

I don't know... @jugmac00, could you help us determining that?

@nteodosio / @tomponline
When I log into a builder in the same region on qastaging, I see the following output:
ubuntu@qastaging-bos03-arm64-001:~$ snap list
Name    Version        Rev    Tracking       Publisher   Notes
core20  20230801       2019   latest/stable  canonical✓  base
lxd     4.0.9-a29c6f1  24065  4.0/stable/…   canonical✓  -
snapd   2.60.4         20298  latest/stable  canonical✓  snapd

@jugmac00 @nteodosio we faced a similar issue on riscv and landed a fix in LXD 5.20 for it here
https://github.com/canonical/lxd/pull/12542
It is our understanding that the riscv builders are currently running latest/candidate, and we've not seen reports of this issue reoccurring on them, so perhaps these builders could also be switched to latest/candidate to see if it reoccurs?

Indeed, we run latest/candidate for the riscv builders.
ubuntu@qastaging-bos03-riscv64-001:~$ snap list
Name    Version       Rev    Tracking          Publisher   Notes
core20  20230126      1827   latest/stable     canonical✓  base
core22  20220425      170    latest/stable     canonical✓  base
lxd     5.20-b670f1a  26586  latest/candidate  canonical✓  -
snapd   2.59.1        19070  latest/stable     canonical✓  snapd

I def. want to have William's opinion on that - not sure he follows github. Maybe we need to move that conversation to Mattermost. Running latest/candidate does sound a bit risky for such a thing as the launchpad buildfarm. When do you expect the changes to land in stable?

Yeah, I deliberately didn't switch other architectures to latest/candidate even though this bug was known to sometimes affect at least arm64 - the plan was to wait until the fix reached at least latest/stable so that Launchpad could use it with a more reasonable amount of production risk.  I think this was in my handover notes.

If Launchpad is still following latest/candidate then it should be using 6.1, but I still very, very
frequently hit this in ARM builds in Launchpad.
buildlog_snap_ubuntu_noble_arm64_chromium-snap-from-source-beta_BUILDING.txt.gz

I've seen this myself on arm64 recently, but they aren't using latest/stable to my knowledge (will check with LP team).
In latest/stable, and 5.21/stable and 5.0/stable we have included the fixes and a revert of the websocket package:
latest/stable: https://github.com/canonical/lxd-pkg-snap/blob/latest-candidate/snapcraft.yaml#L1394-L1395
5.0/stable: https://github.com/canonical/lxd-pkg-snap/blob/5.0-candidate/snapcraft.yaml#L1441
5.21/stable: https://github.com/canonical/lxd/blob/7d4a9933f4618cfe6ec8d18e2e8f91816e5ddbba/lxd/instance_exec.go#L96-L119
So LP should be using one of these versions, so looks like something else.
I'm starting to lose confidence in the websocket package we use so am considering switching to something else.

I can't check any more, but at the time I left, Launchpad was only configured to use latest/candidate on riscv64, and on other architectures it was using whatever the base cloud images in question came with.
I left some notes about this in my handover document to the team; configuration for this lives in lp:~launchpad/launchpad-mojo-specs/+git/private, vbuilder branch, vbuilder/bundle.yaml, the lxd-channel option under the various launchpad-buildd-image-modifier-* applications.

Thanks! We did see an issue recently on riscv64 on latest/candidate, but reverting the websocket package version fixed it. Also it wasn't manifesting as the original I/O timeout error, but instead just a sudden termination of the session without any output.
I am awaiting confirmation from LP team on what channel the arm64 builders use.

and on other architectures it was using whatever the base cloud images in question came with.

So that would be LXD 4.0

Will close this for now until Launchpad gets switched to use 5.21/stable and will re-open if re-occurs.

authors: Debianer GuanglinDu aivanise cjwatson gaia ilya-fedin jugmac00 kochia7 m-ueberall nteodosio pieter-lautus scardracs stgraber tomponline

repo: lxc/lxd