Cluster nodes getting in state where instances are created but are in error state

dgreeley · March 15, 2023, 1:25pm

Hi, I’ve been running into very consistent errors when having an LXD (5.0.2) cluster. The base of the issue is that eventually 1-2 of the nodes out of the 3 nodes in my cluster eventually run into what seems to be a database issue where lxc list on other nodes shows the containers are created but that they are in an ‘ERROR’ state. lxc list also does not work on the node thats failed and the only way to fix it is with systemctl restart snap.lxd.daemon. Also lxc cluster list shows all nodes as ‘healthy’ during this time but obviously thats not the case.

I have created a GH issue for this as well as more logs around the time that it happens. Unfortunately its making me not love clustering anymore due to these recurring issues

github.com/lxc/lxd

Cluster nodes getting in state where instances are created but error when running

opened 02:51PM - 13 Mar 23 UTC

MrDaGree

# Required information All 3 nodes are the same versions listed below * Distribution: Ubuntu * Distribution version: 22.04 <details> <summary>lxc info</summary> ``` environment: addresses: - <node ip addr>:8443 architectures: - x86_64 - i686 certificate: | -----BEGIN CERTIFICATE----- ... -----END CERTIFICATE----- certificate_fingerprint: ... driver: lxc | qemu driver_version: 5.0.2 | 7.1.0 firewall: nftables 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.15.0-67-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: true server_event_mode: full-mesh server_name: <node name> server_pid: 581576 server_version: 5.0.2 storage: zfs storage_version: 2.1.4-0ubuntu0.1 storage_supported_drivers: - name: btrfs version: 5.4.1 remote: false - name: ceph version: 15.2.17 remote: true - name: cephfs version: 15.2.17 remote: true - name: cephobject version: 15.2.17 remote: true - name: dir version: "1" remote: false - name: lvm version: 2.03.07(2) (2019-11-30) / 1.02.167 (2019-11-30) / 4.45.0 remote: false - name: zfs version: 2.1.4-0ubuntu0.1 remote: false ``` </details> * The output of "lxc info" or if that fails: * Kernel version: 5.15.0-67-generic * LXC version: 5.0.2 * LXD version: 5.0.2 * Storage backend in use: ZFS # Issue description Often times I've seen that `lxc list` commands hang for a longer period of time until eventually (on nodes where lxd isn't in a weird state), it shows the status of `ERROR` for instances on the node that is in the bad state. The fix has been running `systemctl restart snap.lxd.daemon` ie, `lxc list` on node6 hangs forever and then `lxc list` on node7 or 0 will eventually populate the list. Node names in cluster: * node0 - .42 * node6 - .202 * node7 - .203 # Information to attach 1. <details> <summary>log from node0 when node6 & node7 were in troubled state</summary> ``` time="2023-03-08T15:25:21-06:00" level=warning msg="Transaction timed out. Retrying once" err="Failed to begin transaction: context deadline exceeded" member=15 time="2023-03-08T15:25:24-06:00" level=warning msg="Heartbeat round duration greater than heartbeat interval" duration=13.985469534s interval=10s time="2023-03-08T15:25:33-06:00" level=warning msg="Transaction timed out. Retrying once" err="Failed to begin transaction: context deadline exceeded" member=15 time="2023-03-08T15:25:33-06:00" level=warning msg="Transaction timed out. Retrying once" err="Failed to begin transaction: context deadline exceeded" member=15 time="2023-03-08T15:25:34-06:00" level=warning msg="Transaction timed out. Retrying once" err="Failed to begin transaction: context deadline exceeded" member=15 time="2023-03-08T15:25:36-06:00" level=warning msg="Excluding offline member from operations by type list" ID=1 address="<node address>.3:8443" lastHeartbeat="2023-03-08 15:25:12.600533501 -0600 -0600" member=node7 opType=28 time="2023-03-08T15:25:39-06:00" level=warning msg="Excluding offline member from operations by type list" ID=1 address="<node address>.3:8443" lastHeartbeat="2023-03-08 15:25:12.600533501 -0600 -0600" member=node7 opType=28 time="2023-03-08T15:25:39-06:00" level=warning msg="Excluding offline member from operations by type list" ID=14 address="<node address>.2:8443" lastHeartbeat="2023-03-08 15:25:18.318737357 -0600 -0600" member=node6 opType=28 time="2023-03-08T15:25:39-06:00" level=warning msg="Heartbeat round duration greater than heartbeat interval" duration=11.966609045s interval=10s time="2023-03-08T15:26:09-06:00" level=warning msg="Heartbeat round duration greater than heartbeat interval" duration=10.334769549s interval=10s time="2023-03-08T15:26:21-06:00" level=warning msg="Transaction timed out. Retrying once" err="Failed to begin transaction: context deadline exceeded" member=15 time="2023-03-08T15:26:22-06:00" level=warning msg="Transaction timed out. Retrying once" err="Failed to begin transaction: context deadline exceeded" member=15 time="2023-03-08T15:26:23-06:00" level=warning msg="Failed to rollback transaction after error (Check if project has images: Failed to fetch from \"project_config\" table: Failed to fetch from \"project_config\" table: context deadline exceeded): sql: transaction has already been committed or rolled back" time="2023-03-08T15:26:23-06:00" level=warning msg="Transaction timed out. Retrying once" err="Check if project has images: Failed to fetch from \"project_config\" table: Failed to fetch from \"project_config\" table: context deadline exceeded" member=15 time="2023-03-08T15:26:27-06:00" level=warning msg="Transaction timed out. Retrying once" err="Failed to begin transaction: context deadline exceeded" member=15 time="2023-03-08T15:26:35-06:00" level=warning msg="Excluding offline member from operations by type list" ID=14 address="<node address>.2:8443" lastHeartbeat="2023-03-08 15:26:05.137456666 -0600 -0600" member=node6 opType=28 time="2023-03-08T15:26:35-06:00" level=warning msg="Excluding offline member from operations by type list" ID=1 address="<node address>.3:8443" lastHeartbeat="2023-03-08 15:26:05.599351057 -0600 -0600" member=node7 opType=28 time="2023-03-08T15:26:41-06:00" level=warning msg="Transaction timed out. Retrying once" err="Failed to begin transaction: context deadline exceeded" member=15 time="2023-03-08T15:26:42-06:00" level=warning msg="Transaction timed out. Retrying once" err="Failed to begin transaction: context deadline exceeded" member=15 ``` </details> 1. <details> <summary>log from node7 when node6 & node7 were in troubled state</summary> ``` time="2023-03-09T08:22:20-06:00" level=error msg="Failed writing error for HTTP response" err="Get \"https://<node address>.2:8443/1.0/instances/<instance name>\": net/http: timeout awaiting response headers" url="/1.0/instances/{name}" writeErr="<nil>" time="2023-03-09T08:23:49-06:00" level=error msg="Failed writing error for HTTP response" err="Get \"https://<node address>.2:8443/1.0/instances/<instance name>\": net/http: timeout awaiting response headers" url="/1.0/instances/{name}" writeErr="<nil>" time="2023-03-09T08:24:37-06:00" level=error msg="Failed writing error for HTTP response" err="Get \"https://<node address>.2:8443/1.0/instances/<instance name>\": net/http: timeout awaiting response headers" url="/1.0/instances/{name}" writeErr="<nil>" time="2023-03-09T08:27:18-06:00" level=error msg="Failed writing error for HTTP response" err="Get \"https://<node address>.2:8443/1.0/instances/<instance name>\": net/http: timeout awaiting response headers" url="/1.0/instances/{name}" writeErr="<nil>" time="2023-03-09T08:28:48-06:00" level=error msg="Failed writing error for HTTP response" err="Get \"https://<node address>.2:8443/1.0/instances/<instance name>\": net/http: timeout awaiting response headers" url="/1.0/instances/{name}" writeErr="<nil>" time="2023-03-09T08:31:56-06:00" level=error msg="Failed writing error for HTTP response" err="open /var/snap/lxd/common/lxd/logs/<instance name>/qemu.log: no such file or directory" url="/1.0/instances/{name}/logs/{file}" writeErr="<nil>" time="2023-03-09T08:32:58-06:00" level=error msg="Failed writing error for HTTP response" err="Get \"https://<node address>.2:8443/1.0/instances/<instance name>\": net/http: timeout awaiting response headers" url="/1.0/instances/{name}" writeErr="<nil>" time="2023-03-09T08:33:48-06:00" level=error msg="Failed writing error for HTTP response" err="Get \"https://<node address>.2:8443/1.0/instances/<instance name>\": net/http: timeout awaiting response headers" url="/1.0/instances/{name}" writeErr="<nil>" time="2023-03-09T08:34:43-06:00" level=error msg="Failed writing error for HTTP response" err="Get \"https://<node address>.2:8443/1.0/instances/<instance name>\": net/http: timeout awaiting response headers" url="/1.0/instances/{name}" writeErr="<nil>" ``` </details> 1. <details> <summary>log from node6 this morning when it was in a troubled state</summary> ``` time="2023-03-11T15:29:44-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T15:30:30-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T15:40:43-06:00" level=warning msg="Excluding offline member from operations by type list" ID=15 address="<node ipaddress>.2:8443" lastHeartbeat="2023-03-11 15:40:19.459078405 -0600 -0600" member=node0 opType=28 time="2023-03-11T15:40:43-06:00" level=warning msg="Excluding offline member from operations by type list" ID=1 address="<node ipaddress>.3:8443" lastHeartbeat="2023-03-11 15:40:22.509568256 -0600 -0600" member=node7 opType=28 time="2023-03-11T15:50:35-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T15:50:36-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T15:50:42-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T15:54:58-06:00" level=warning msg="Excluding offline member from operations by type list" ID=1 address="<node ipaddress>.3:8443" lastHeartbeat="2023-03-11 15:54:35.039073046 -0600 -0600" member=node7 opType=28 time="2023-03-11T15:54:58-06:00" level=warning msg="Excluding offline member from operations by type list" ID=15 address="<node ipaddress>.2:8443" lastHeartbeat="2023-03-11 15:54:33.27048227 -0600 -0600" member=node0 opType=28 time="2023-03-11T16:18:56-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T16:19:15-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T16:26:19-06:00" level=error msg="Failed writing error for HTTP response" err="open /var/snap/lxd/common/lxd/images/21f7d9bd58e31c0e7d113c9383d7180923faa238fd15e36cb4895f72915e47e2: no such file or directory" url="/1.0/images/{fingerprint}/export" writeErr="<nil>" time="2023-03-11T17:26:27-06:00" level=error msg="Failed writing error for HTTP response" err="open /var/snap/lxd/common/lxd/images/21f7d9bd58e31c0e7d113c9383d7180923faa238fd15e36cb4895f72915e47e2: no such file or directory" url="/1.0/images/{fingerprint}/export" writeErr="<nil>" time="2023-03-11T17:33:39-06:00" level=warning msg="Failed getting exec control websocket reader, killing command" PID=1108890 err="websocket: close 1006 (abnormal closure): unexpected EOF" instance=test-instance1 interactive=false project=default time="2023-03-11T17:34:29-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T17:37:04-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T17:53:05-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T17:57:23-06:00" level=error msg="Failed writing error for HTTP response" err="open /var/snap/lxd/common/lxd/logs/<instance>/qemu.log: no such file or directory" url="/1.0/instances/{name}/logs/{file}" writeErr="<nil>" time="2023-03-11T18:13:48-06:00" level=error msg="Failed writing error for HTTP response" err="open /var/snap/lxd/common/lxd/logs/<instance>/qemu.log: no such file or directory" url="/1.0/instances/{name}/logs/{file}" writeErr="<nil>" time="2023-03-11T18:14:36-06:00" level=warning msg="Could not apply quota because disk is in use, deferring until next start" device=root driver=disk instance=test-instance2 project=default time="2023-03-11T18:14:48-06:00" level=warning msg="Failed cleaning up config drive mount" err="Failed unmounting \"/var/snap/lxd/common/lxd/devices/<instance>/config.mount\": Failed to unmount \"/var/snap/lxd/common/lxd/devices/<instance>/config.mount\": device or resource busy" instance=test-instance1 instanceType=virtual-machine project=default time="2023-03-11T18:15:18-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T18:16:41-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T18:17:05-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T18:18:08-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T18:18:08-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T18:18:26-06:00" level=error msg="Failed writing error for HTTP response" err="open /var/snap/lxd/common/lxd/logs/<instance>/qemu.log: no such file or directory" url="/1.0/instances/{name}/logs/{file}" writeErr="<nil>" time="2023-03-11T18:20:50-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T18:23:16-06:00" level=error msg="Failed writing error for HTTP response" err="Only running operations can be connected" url="/1.0/operations/{id}/websocket" writeErr="<nil>" time="2023-03-11T18:26:28-06:00" level=error msg="Failed writing error for HTTP response" err="open /var/snap/lxd/common/lxd/images/21f7d9bd58e31c0e7d113c9383d7180923faa238fd15e36cb4895f72915e47e2: no such file or directory" url="/1.0/images/{fingerprint}/export" writeErr="<nil>" ``` </details> I do keep forgetting to run `lxc info <name> --show-log` on the instances when I fix this bug hopefully soon when it breaks again I can do that on a node where its actually working. Do let me know of any additional information that may be helpful.

tomp · March 21, 2023, 4:52pm

Please can you describe more about your setup (hardware, network etc).

Also please can you provide the output of lxc cluster list before and after the issues start.
Please can you also explain what is happening in the cluster when the problem starts, or whether there are particular timings until the problems start.

Finally, please can you explain about your cluster member names, they look a little odd. Is this just so they line up with the host name of the servers or have you added/removed cluster members in the past?