randombenj commented 1 year ago

Required information

Distribution: ubuntu
Distribution version: 20.04

The output of "lxc info":

config: {}
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
- instance_nic_routed_neighbor_probe
- event_hub
- agent_nic_config
- projects_restricted_intercept
- metrics_authentication
- images_target_project
- cluster_migration_inconsistent_copy
- cluster_ovn_chassis
- container_syscall_intercept_sched_setscheduler
- storage_lvm_thinpool_metadata_size
- storage_volume_state_total
- instance_file_head
- instances_nic_host_name
- image_copy_profile
- container_syscall_intercept_sysinfo
- clustering_evacuation_mode
- resources_pci_vpd
- qemu_raw_conf
- storage_cephfs_fscache
- network_load_balancer
- vsock_api
- instance_ready_state
- network_bgp_holdtime
- storage_volumes_all_projects
- metrics_memory_oom_total
- storage_buckets
- storage_buckets_create_credentials
- metrics_cpu_effective_total
- projects_networks_restricted_access
- storage_buckets_local
- loki
- acme
- internal_metrics
- cluster_join_token_expiry
- remote_token_expiry
- init_preseed
- storage_volumes_created_at
- cpu_hotplug
- projects_networks_zones
api_status: stable
api_version: "1.0"
auth: trusted
public: false
auth_methods:
- tls
environment:
addresses: []
architectures:
- x86_64
- i686
certificate: |
-----BEGIN CERTIFICATE-----
MIICGDCCAZ6gAwIBAgIQdMUrFXYUmz2PqPlK/LQ+ATAKBggqhkjOPQQDAzA7MRww
GgYDVQQKExNsaW51eGNvbnRhaW5lcnMub3JnMRswGQYDVQQDDBJyb290QHJyb3V3
cHJsYzAwMTEwHhcNMjIxMjE1MTIxMTM2WhcNMzIxMjEyMTIxMTM2WjA7MRwwGgYD
VQQKExNsaW51eGNvbnRhaW5lcnMub3JnMRswGQYDVQQDDBJyb290QHJyb3V3cHJs
YzAwMTEwdjAQBgcqhkjOPQIBBgUrgQQAIgNiAATF1BhM+YSOGWCM8RvuwRhye4Dy
8Ai6sjoj63/Ts7kXgryus6V+wKL/x/9w8gRMDUH97BBXw06X7FwQUpc/gdqQXKgO
WfZOrj2gSOZjmT7lYARxVq59bYpIN4a9h1mN4cKjZzBlMA4GA1UdDwEB/wQEAwIF
oDATBgNVHSUEDDAKBggrBgEFBQcDATAMBgNVHRMBAf8EAjAAMDAGA1UdEQQpMCeC
DXJyb3V3cHJsYzAwMTGHBH8AAAGHEAAAAAAAAAAAAAAAAAAAAAEwCgYIKoZIzj0E
AwMDaAAwZQIxAJJP6+biK6bNQOaE+Iq15fx6QROK11EHzLdTirC3iusFZ+u7EbJd
ed7nVadGRl1PQAIwN306ElpYUo73tNQpEN5Slh7KRXu38sefmF1uU4EMCGZR7ke7
iLXQnAdaHADjWUYZ
-----END CERTIFICATE-----
certificate_fingerprint: c1cf2053f41f3f67434acd29b932ae09529a610049759ac135a2f1c4bf11a24e
driver: lxc | qemu
driver_version: 4.0.12 | 4.2.1
firewall: xtables
kernel: Linux
kernel_architecture: x86_64
kernel_features:
idmapped_mounts: "true"
netnsid_getifaddrs: "true"
seccomp_listener: "true"
seccomp_listener_continue: "true"
shiftfs: "false"
uevent_injection: "true"
unpriv_fscaps: "true"
kernel_version: 5.14.0-1056-oem
lxc_features:
cgroup2: "true"
core_scheduling: "true"
devpts_fd: "true"
idmapped_mounts_v2: "true"
mount_injection_file: "true"
network_gateway_device_route: "true"
network_ipvlan: "true"
network_l2proxy: "true"
network_phys_macvlan_mtu: "true"
network_veth_router: "true"
pidfd: "true"
seccomp_allow_deny_syntax: "true"
seccomp_notify: "true"
seccomp_proxy_send_notify_fd: "true"
os_name: Ubuntu
os_version: "20.04"
project: default
server: lxd
server_clustered: false
server_event_mode: full-mesh
server_name: rrouwprlc0011
server_pid: 828009
server_version: "5.9"
storage: dir
storage_version: "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: 0.8.3-1ubuntu12.14
remote: false
- name: btrfs
version: 5.4.1
remote: false

Issue description

When mounting a nfs share inside a container, the container deletion times out. Steps to reproduce:

Steps to reproduce

lxc launch images:ubuntu/20.04 -c security.privileged=true c
lxc shell c -- "apt update && apt install --yes cifs-utils"
lxc shell c -- "mkdir /mnt/m1 && mount -t cifs //tonne/ /mnt/m1/"
lxc rm -f c

Will result in:

Error: Stopping the instance failed: Instance "stop" operation timed out after 30s

Information to attach

[ ] Any relevant kernel output (dmesg)
[ ] Container log (lxc info NAME --show-log)
[ ] Container configuration (lxc config show NAME --expanded)
[ ] Main daemon log (at /var/log/lxd/lxd.log or /var/snap/lxd/common/lxd/logs/lxd.log)
[ ] Output of the client with --debug
[ ] Output of the daemon with --debug (alternatively output of lxc monitor while reproducing the issue)

tomponline commented 1 year ago

Please can you get the lxc info NAME --show-log output after the timeout has occurred, along with lxc monitor --type=logging --pretty output from the point where the lxc rm command is started.

randombenj commented 1 year ago

Interesting observation, when running lxc rm -f c the second time (after the timeout) the container is deleted.

$ lxc info c --show-log
Name: c
Status: STOPPED
Type: container
Architecture: x86_64
Created: 2023/03/01 15:19 CET
Last Used: 2023/03/01 15:19 CET

Log:

LXC Monitor:

DEBUG  [2023-03-01T15:38:45+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0 username=fassbinb
DEBUG  [2023-03-01T15:38:45+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/instances/c username=fassbinb
DEBUG  [2023-03-01T15:38:45+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/instances/c username=fassbinb
DEBUG  [2023-03-01T15:38:45+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/events username=fassbinb
DEBUG  [2023-03-01T15:38:45+01:00] Event listener server handler started         id=5c1e5fce-bcef-40aa-8d1e-241dd4f97820 local=/var/lib/lxd/unix.socket remote=@
DEBUG  [2023-03-01T15:38:45+01:00] Handling API request                          ip=@ method=PUT protocol=unix url=/1.0/instances/c/state username=fassbinb
DEBUG  [2023-03-01T15:38:45+01:00] Stop started                                  instance=c instanceType=container project=default stateful=false
DEBUG  [2023-03-01T15:38:45+01:00] Started operation                             class=task description="Stopping instance" operation=63c368fa-cb5f-43ab-8202-0158795f58e2 project=default
DEBUG  [2023-03-01T15:38:45+01:00] New operation                                 class=task description="Stopping instance" operation=63c368fa-cb5f-43ab-8202-0158795f58e2 project=default
DEBUG  [2023-03-01T15:38:45+01:00] Instance operation lock created               action=stop instance=c project=default reusable=false
INFO   [2023-03-01T15:38:45+01:00] Stopping container                            action=stop created="2023-03-01 14:37:43.34485976 +0000 UTC" ephemeral=false instance=c instanceType=container project=default stateful=false used="2023-03-01 14:37:45.957676119 +0000 UTC"
DEBUG  [2023-03-01T15:38:45+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/operations/63c368fa-cb5f-43ab-8202-0158795f58e2 username=fassbinb
DEBUG  [2023-03-01T15:38:46+01:00] Scheduler: network: eth0 has been added: updating network priorities 
DEBUG  [2023-03-01T15:38:46+01:00] Handling API request                          ip=@ method=GET protocol=unix url="/internal/containers/c/onstopns?netns=%2Fproc%2F2459072%2Ffd%2F49&project=default&target=stop" username=root
DEBUG  [2023-03-01T15:38:46+01:00] Stopping device                               device=eth0 instance=c instanceType=container project=default type=nic
DEBUG  [2023-03-01T15:39:15+01:00] Instance operation lock finished              action=stop err="Instance \"stop\" operation timed out after 30s" instance=c project=default reusable=false
DEBUG  [2023-03-01T15:41:42+01:00] Handling API request                          ip=@ method=GET protocol=unix url="/internal/containers/c/onstop?project=default&target=stop" username=root
DEBUG  [2023-03-01T15:41:42+01:00] Instance operation lock created               action=stop instance=c project=default reusable=false
DEBUG  [2023-03-01T15:41:42+01:00] Instance initiated stop                       action=stop instance=c instanceType=container project=default
DEBUG  [2023-03-01T15:41:42+01:00] Container stopped, cleaning up                instance=c instanceType=container project=default
DEBUG  [2023-03-01T15:41:42+01:00] Stopping device                               device=root instance=c instanceType=container project=default type=disk
DEBUG  [2023-03-01T15:41:42+01:00] UnmountInstance started                       instance=c project=default
DEBUG  [2023-03-01T15:41:42+01:00] UnmountInstance finished                      instance=c project=default
DEBUG  [2023-03-01T15:41:42+01:00] Failure for operation                         class=task description="Stopping instance" err="Instance \"stop\" operation timed out after 30s" operation=63c368fa-cb5f-43ab-8202-0158795f58e2 project=default
DEBUG  [2023-03-01T15:41:42+01:00] Stop finished                                 instance=c instanceType=container project=default stateful=false
DEBUG  [2023-03-01T15:41:42+01:00] Event listener server handler stopped         listener=5c1e5fce-bcef-40aa-8d1e-241dd4f97820 local=/var/lib/lxd/unix.socket remote=@
DEBUG  [2023-03-01T15:41:43+01:00] Scheduler: container c stopped: re-balancing 
DEBUG  [2023-03-01T15:41:43+01:00] Instance operation lock finished              action=stop err="<nil>" instance=c project=default reusable=false
INFO   [2023-03-01T15:41:43+01:00] Shut down container                           action=stop created="2023-03-01 14:37:43.34485976 +0000 UTC" ephemeral=false instance=c instanceType=container project=default stateful=false used="2023-03-01 14:37:45.957676119 +0000 UTC"

Log of the second lxc rm -f c monitor:

DEBUG  [2023-03-01T15:42:50+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0 username=fassbinb
DEBUG  [2023-03-01T15:42:50+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/instances/c username=fassbinb
DEBUG  [2023-03-01T15:42:50+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/instances/c username=fassbinb
DEBUG  [2023-03-01T15:42:50+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/events username=fassbinb
DEBUG  [2023-03-01T15:42:50+01:00] Event listener server handler started         id=5c49d364-9433-46a9-b8fd-30c46434d705 local=/var/lib/lxd/unix.socket remote=@
DEBUG  [2023-03-01T15:42:50+01:00] Handling API request                          ip=@ method=DELETE protocol=unix url=/1.0/instances/c username=fassbinb
DEBUG  [2023-03-01T15:42:50+01:00] Instance operation lock created               action=delete instance=c project=default reusable=false
DEBUG  [2023-03-01T15:42:50+01:00] New operation                                 class=task description="Deleting instance" operation=67361a29-c132-4f22-b3d9-71c7bb06bb6c project=default
DEBUG  [2023-03-01T15:42:50+01:00] Started operation                             class=task description="Deleting instance" operation=67361a29-c132-4f22-b3d9-71c7bb06bb6c project=default
INFO   [2023-03-01T15:42:50+01:00] Deleting container                            created="2023-03-01 14:37:43.34485976 +0000 UTC" ephemeral=false instance=c instanceType=container project=default used="2023-03-01 14:37:45.957676119 +0000 UTC"
DEBUG  [2023-03-01T15:42:50+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/operations/67361a29-c132-4f22-b3d9-71c7bb06bb6c username=fassbinb
DEBUG  [2023-03-01T15:42:50+01:00] DeleteInstance started                        instance=c project=default
DEBUG  [2023-03-01T15:42:50+01:00] Deleting instance volume                      instance=c project=default volName=c
DEBUG  [2023-03-01T15:42:50+01:00] DeleteInstance finished                       instance=c project=default
DEBUG  [2023-03-01T15:42:50+01:00] Removing device                               device=root instance=c instanceType=container project=default type=disk
DEBUG  [2023-03-01T15:42:50+01:00] Removing device                               device=eth0 instance=c instanceType=container project=default type=nic
DEBUG  [2023-03-01T15:42:50+01:00] Success for operation                         class=task description="Deleting instance" operation=67361a29-c132-4f22-b3d9-71c7bb06bb6c project=default
DEBUG  [2023-03-01T15:42:50+01:00] Instance operation lock finished              action=delete err="<nil>" instance=c project=default reusable=false
INFO   [2023-03-01T15:42:50+01:00] Deleted container                             created="2023-03-01 14:37:43.34485976 +0000 UTC" ephemeral=false instance=c instanceType=container project=default used="2023-03-01 14:37:45.957676119 +0000 UTC"
DEBUG  [2023-03-01T15:42:50+01:00] Event listener server handler stopped         listener=5c49d364-9433-46a9-b8fd-30c46434d705 local=/var/lib/lxd/unix.socket remote=@

tomponline commented 1 year ago

Hi,

Thanks for this.

Please can you confirm if this is still in an issue in LXD 5.11, as LXD 5.9 isn't supported anymore.

fliiiix commented 1 year ago

Can confirm for installed: 5.11-ad0b61e needed to add security.nesting=true

 lxc rm -f container 
Error: Stopping the instance failed: Failed stopping instance, status is "Running": Instance "stop" operation timed out after 30s

also from dmesg

[199564.457146] CIFS: VFS: \\CFIS-Server has not responded in 180 seconds. Reconnecting...
[199564.461730] CIFS: VFS: \\CFIS-Server has not responded in 180 seconds. Reconnecting...

tomponline commented 1 year ago

How long do you have to wait if you do lxc stop c (without -f), also can you show the debug monitor output for this too.

tomponline commented 1 year ago

I would also like to see the LXD 5.11 monitor debug output for lxc stop -f c as some of the messages have changed since LXD 5.9.

fliiiix commented 1 year ago

time lxc stop -f c
Error: Failed stopping instance, status is "Running": Instance "stop" operation timed out after 30s
Try `lxc info --show-log c` for more info
lxc stop -f c  0.06s user 0.09s system 0% cpu 2:31.84 total

and logs

DEBUG  [2023-03-01T16:40:14+01:00] Event listener server handler started         id=48fdf5d0-9998-4469-b1f8-2693fc6432c0 local=/var/snap/lxd/common/lxd/unix.socket remote=@
DEBUG  [2023-03-01T16:40:17+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0 username="uid=81448"
DEBUG  [2023-03-01T16:40:17+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/events username="uid=81448"
DEBUG  [2023-03-01T16:40:17+01:00] Event listener server handler started         id=2ec7a3fe-2231-4604-9eba-6867a99aec07 local=/var/snap/lxd/common/lxd/unix.socket remote=@
DEBUG  [2023-03-01T16:40:17+01:00] Handling API request                          ip=@ method=PUT protocol=unix url=/1.0/instances/c/state username="uid=81448"
DEBUG  [2023-03-01T16:40:17+01:00] New operation                                 class=task description="Stopping instance" operation=8dd7a7fe-c06b-45b2-b53a-584737d4e067 project=default
DEBUG  [2023-03-01T16:40:17+01:00] Stop started                                  instance=c instanceType=container project=default stateful=false
DEBUG  [2023-03-01T16:40:17+01:00] Started operation                             class=task description="Stopping instance" operation=8dd7a7fe-c06b-45b2-b53a-584737d4e067 project=default
DEBUG  [2023-03-01T16:40:17+01:00] Instance operation lock created               action=stop instance=c project=default reusable=false
INFO   [2023-03-01T16:40:17+01:00] Stopping instance                             action=stop created="2023-03-01 15:37:38.876997917 +0000 UTC" ephemeral=false instance=c instanceType=container project=default stateful=false used="2023-03-01 15:37:39.556369868 +0000 UTC"
DEBUG  [2023-03-01T16:40:17+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/operations/8dd7a7fe-c06b-45b2-b53a-584737d4e067 username="uid=81448"
DEBUG  [2023-03-01T16:40:17+01:00] Scheduler: network: eth0 has been added: updating network priorities 
DEBUG  [2023-03-01T16:40:17+01:00] Handling API request                          ip=@ method=GET protocol=unix url="/internal/containers/c/onstopns?netns=%2Fproc%2F1239387%2Ffd%2F49&project=default&target=stop" username=root
DEBUG  [2023-03-01T16:40:17+01:00] Instance operation lock inherited for stop    action=stop instance=c instanceType=container project=default
DEBUG  [2023-03-01T16:40:17+01:00] Stopping device                               device=eth0 instance=c instanceType=container project=default type=nic
DEBUG  [2023-03-01T16:40:47+01:00] Instance operation lock finished              action=stop err="Instance \"stop\" operation timed out after 30s" instance=c project=default reusable=false
DEBUG  [2023-03-01T16:42:48+01:00] Handling API request                          ip=@ method=GET protocol=unix url="/internal/containers/c/onstop?project=default&target=stop" username=root
DEBUG  [2023-03-01T16:42:48+01:00] Instance initiated stop                       action=stop instance=c instanceType=container project=default
DEBUG  [2023-03-01T16:42:48+01:00] Instance operation lock created               action=stop instance=c project=default reusable=false
DEBUG  [2023-03-01T16:42:48+01:00] Instance stopped, cleaning up                 instance=c instanceType=container project=default
DEBUG  [2023-03-01T16:42:48+01:00] Stopping device                               device=root instance=c instanceType=container project=default type=disk
DEBUG  [2023-03-01T16:42:48+01:00] Stop finished                                 instance=c instanceType=container project=default stateful=false
DEBUG  [2023-03-01T16:42:48+01:00] Failure for operation                         class=task description="Stopping instance" err="Failed stopping instance, status is \"Running\": Instance \"stop\" operation timed out after 30s" operation=8dd7a7fe-c06b-45b2-b53a-584737d4e067 project=default
DEBUG  [2023-03-01T16:42:48+01:00] UnmountInstance started                       instance=c project=default
DEBUG  [2023-03-01T16:42:48+01:00] Event listener server handler stopped         listener=2ec7a3fe-2231-4604-9eba-6867a99aec07 local=/var/snap/lxd/common/lxd/unix.socket remote=@
DEBUG  [2023-03-01T16:42:49+01:00] UnmountInstance finished                      instance=c project=default
DEBUG  [2023-03-01T16:42:49+01:00] Unmounted ZFS dataset                         dev=default/containers/c driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/default/containers/c pool=default volName=c
DEBUG  [2023-03-01T16:42:49+01:00] Scheduler: container c stopped: re-balancing 
INFO   [2023-03-01T16:42:49+01:00] Shut down instance                            action=stop created="2023-03-01 15:37:38.876997917 +0000 UTC" ephemeral=false instance=c instanceType=container project=default stateful=false used="2023-03-01 15:37:39.556369868 +0000 UTC"
DEBUG  [2023-03-01T16:42:49+01:00] Instance operation lock finished              action=stop err="<nil>" instance=c project=default reusable=false

time lxc stop c                                                                         
lxc stop c  0.07s user 0.08s system 10% cpu 1.399 total

DEBUG  [2023-03-01T16:45:43+01:00] Event listener server handler started         id=659a41ab-2e6f-4ce6-9378-b6dc742d338c local=/var/snap/lxd/common/lxd/unix.socket remote=@
DEBUG  [2023-03-01T16:45:58+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0 username="uid=81448"
DEBUG  [2023-03-01T16:45:58+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/events username="uid=81448"
DEBUG  [2023-03-01T16:45:58+01:00] Event listener server handler started         id=a3e849ae-3e9a-4103-95cb-2b17f4850e08 local=/var/snap/lxd/common/lxd/unix.socket remote=@
DEBUG  [2023-03-01T16:45:58+01:00] Handling API request                          ip=@ method=PUT protocol=unix url=/1.0/instances/c/state username="uid=81448"
DEBUG  [2023-03-01T16:45:58+01:00] Started operation                             class=task description="Stopping instance" operation=ea60e31d-5a15-4502-a774-18034edf9c78 project=default
DEBUG  [2023-03-01T16:45:58+01:00] New operation                                 class=task description="Stopping instance" operation=ea60e31d-5a15-4502-a774-18034edf9c78 project=default
DEBUG  [2023-03-01T16:45:58+01:00] Shutdown started                              instance=c instanceType=container project=default timeout=-1s
DEBUG  [2023-03-01T16:45:58+01:00] Instance operation lock created               action=stop instance=c project=default reusable=true
INFO   [2023-03-01T16:45:58+01:00] Shutting down instance                        action=shutdown created="2023-03-01 15:44:32.68628724 +0000 UTC" ephemeral=false instance=c instanceType=container project=default timeout=-1s used="2023-03-01 15:44:33.396579726 +0000 UTC"
DEBUG  [2023-03-01T16:45:58+01:00] Shutdown request sent to instance             instance=c instanceType=container project=default
DEBUG  [2023-03-01T16:45:58+01:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0/operations/ea60e31d-5a15-4502-a774-18034edf9c78 username="uid=81448"
DEBUG  [2023-03-01T16:45:58+01:00] Scheduler: network: eth0 has been added: updating network priorities 
DEBUG  [2023-03-01T16:45:58+01:00] Handling API request                          ip=@ method=GET protocol=unix url="/internal/containers/c/onstopns?netns=%2Fproc%2F1245477%2Ffd%2F49&project=default&target=stop" username=root
DEBUG  [2023-03-01T16:45:58+01:00] Instance operation lock inherited for stop    action=stop instance=c instanceType=container project=default
DEBUG  [2023-03-01T16:45:58+01:00] Stopping device                               device=eth0 instance=c instanceType=container project=default type=nic
DEBUG  [2023-03-01T16:45:59+01:00] Handling API request                          ip=@ method=GET protocol=unix url="/internal/containers/c/onstop?project=default&target=stop" username=root
DEBUG  [2023-03-01T16:45:59+01:00] Instance operation lock inherited for stop    action=stop instance=c instanceType=container project=default
DEBUG  [2023-03-01T16:45:59+01:00] Instance stopped, cleaning up                 instance=c instanceType=container project=default
DEBUG  [2023-03-01T16:45:59+01:00] Stopping device                               device=root instance=c instanceType=container project=default type=disk
DEBUG  [2023-03-01T16:45:59+01:00] UnmountInstance started                       instance=c project=default
DEBUG  [2023-03-01T16:45:59+01:00] UnmountInstance finished                      instance=c project=default
DEBUG  [2023-03-01T16:45:59+01:00] Unmounted ZFS dataset                         dev=default/containers/c driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/default/containers/c pool=default volName=c
DEBUG  [2023-03-01T16:45:59+01:00] Scheduler: container c stopped: re-balancing 
DEBUG  [2023-03-01T16:45:59+01:00] Instance operation lock finished              action=stop err="<nil>" instance=c project=default reusable=true
DEBUG  [2023-03-01T16:45:59+01:00] Shutdown finished                             instance=c instanceType=container project=default timeout=-1s
DEBUG  [2023-03-01T16:45:59+01:00] Success for operation                         class=task description="Stopping instance" operation=ea60e31d-5a15-4502-a774-18034edf9c78 project=default
DEBUG  [2023-03-01T16:45:59+01:00] Event listener server handler stopped         listener=a3e849ae-3e9a-4103-95cb-2b17f4850e08 local=/var/snap/lxd/common/lxd/unix.socket remote=@

fliiiix commented 1 year ago

@tomponline this issue is still labeled as incomplete what else is missing?

tomponline commented 1 year ago

@roosterfish want to take a look at this one when you get chance?

mihalicyn commented 1 year ago

My hypothesis that this is a consequence of network disabling during shutdown. We shooting in our own leg here, network is down, then we want do destroy mount namespace, to do that we need to unmount all the mounts but CIFS uses network and can't be properly unmounted because network is not accessible anymore.

@fliiiix can you reproduce the problem and show the output of this thing ps aux | awk '{ if ($8 == "D") { print } }'? If you see non-empty output then take a numeric value from a second column (PID) and also post cat /proc/<PID>/stack output here.

roosterfish commented 1 year ago

@mihalicyn I reproduced the issue. The command ps aux | awk '{ if ($8 == "D") { print } }' unfortunately doesn't show anything on the host during the deletion of the container.

What I can also see are the dmesg messages as reported by @fliiiix:

[12975.341511] CIFS: VFS: \\10.159.171.106 has not responded in 180 seconds. Reconnecting...

mihalicyn commented 1 year ago

@roosterfish it seems interesting. Can you post the output of cat /proc/*/stack somewhere like pastebin/gists? This output should be collected when you've lxc stop process running and stuck.

roosterfish commented 1 year ago

@roosterfish it seems interesting. Can you post the output of cat /proc/*/stack somewhere like pastebin/gists? This output should be collected when you've lxc stop process running and stuck.

I have collected a few (every second). Here is one from the beginning right after lxc delete -f was called:

https://pastebin.ubuntu.com/p/m3dtVs5GZB/

And this one is a few seconds before lxc delete -f returns:

https://pastebin.ubuntu.com/p/TGkHT6rKhC/

mihalicyn commented 1 year ago

O! Thanks, Julian!

Now let's see:

[<0>] wait_for_response+0xb0/0x150 [cifs]
[<0>] compound_send_recv+0x5bd/0x11b0 [cifs]
[<0>] cifs_send_recv+0x22/0x40 [cifs]
[<0>] SMB2_tdis+0x18a/0x250 [cifs]
[<0>] cifs_put_tcon.part.0+0xc0/0x260 [cifs]
[<0>] cifs_put_tlink+0x4a/0x90 [cifs]
[<0>] cifs_umount+0x59/0xc0 [cifs]
[<0>] cifs_kill_sb+0xae/0xd0 [cifs]
[<0>] deactivate_locked_super+0x32/0xb0
[<0>] deactivate_super+0x4a/0x60
[<0>] cleanup_mnt+0x150/0x1e0
[<0>] __cleanup_mnt+0x12/0x20
[<0>] task_work_run+0x61/0xa0
[<0>] exit_to_user_mode_loop+0x111/0x140
[<0>] exit_to_user_mode_prepare+0xb9/0xd0
[<0>] syscall_exit_to_user_mode+0x2a/0x50
[<0>] do_syscall_64+0x69/0x90
[<0>] entry_SYSCALL_64_after_hwframe+0x63/0xcd

That's exactly what I've suspected. We have __cleanup_mnt on the callstack which is executed from a context of a task work before exiting from a syscall to a user space (link https://github.com/torvalds/linux/blob/fdf0eaf11452d72945af31804e2a1048ee1b574c/fs/namespace.c#L1332). This happens from mntput_no_expire function which is called from many places, but most important one is mntput (link https://github.com/torvalds/linux/blob/fdf0eaf11452d72945af31804e2a1048ee1b574c/fs/namespace.c#L1343).

I think that this bug is more about LXC/Linux kernel rather than LXD. I'm ready to take a look on that closely but later because it can result in a lot of work to fix it properly.

It would be great if you share your reproducer and your test setup for CIFS. It will be useful for us in a near future.

tomponline commented 1 year ago

@roosterfish @mihalicyn shall we move this to lxc repo and close this one then?

mihalicyn commented 1 year ago

yes, I think it fits better to LXC issue tracker

roosterfish commented 1 year ago

Reproducer steps:

lxc launch ubuntu:jammy vm1 --vm
lxc exec vm1 apt install samba
Create a directory /data on vm1 and share it by appending to the samba config (/etc/samba/smb.conf):

[sambashare]
path = /data
read only = no
browsable = yes

lxc exec vm1 service smbd restart
lxc exec vm1 smbpasswd -a root -> set a password for the root user
lxc exec vm1 smbpasswd -e root -> enable root

Start a new privileged container and mount in the samba share:

lxc launch ubuntu:jammy c1 -c security.privileged=true
lxc exec c1 apt install cifs-utils
lxc exec c1 mount -t cifs //{IP of vm1}/sambashare /mnt -> enter password from before
lxc delete -f c1 -> boom!

mihalicyn commented 1 year ago

Fantastic! Thanks a lot, Julian!

tomponline commented 1 year ago

@roosterfish please can you post this over at https://github.com/lxc/lxc/issues and link to it here when you're done.

canonical / lxd

Delete timeout when container has a cifs mount point #11421

Required information

Issue description

Steps to reproduce

Information to attach