Lxd 3.23, lxc exec bash hangs

LXD
1

Hello,

lxc exec hangs on my system, the host is running ArchLinux. lxc console works fine. Any idea what could be the issue?

Here is the LXD log

# cat /var/snap/lxd/common/lxd/logs/lxd.log
t=2020-03-27T07:35:15+0530 lvl=info msg="LXD 3.23 is starting in normal mode" path=/var/snap/lxd/common/lxd
t=2020-03-27T07:35:15+0530 lvl=info msg="Kernel uid/gid map:" 
t=2020-03-27T07:35:15+0530 lvl=info msg=" - u 0 0 4294967295" 
t=2020-03-27T07:35:15+0530 lvl=info msg=" - g 0 0 4294967295" 
t=2020-03-27T07:35:15+0530 lvl=info msg="Configured LXD uid/gid map:" 
t=2020-03-27T07:35:15+0530 lvl=info msg=" - u 0 1000000 1000000000" 
t=2020-03-27T07:35:15+0530 lvl=info msg=" - g 0 1000000 1000000000" 
t=2020-03-27T07:35:15+0530 lvl=warn msg="AppArmor support has been disabled because of lack of kernel support" 
t=2020-03-27T07:35:15+0530 lvl=info msg="Kernel features:" 
t=2020-03-27T07:35:15+0530 lvl=info msg=" - netnsid-based network retrieval: yes" 
t=2020-03-27T07:35:15+0530 lvl=info msg=" - uevent injection: yes" 
t=2020-03-27T07:35:15+0530 lvl=info msg=" - seccomp listener: yes" 
t=2020-03-27T07:35:15+0530 lvl=info msg=" - seccomp listener continue syscalls: no" 
t=2020-03-27T07:35:15+0530 lvl=info msg=" - unprivileged file capabilities: yes" 
t=2020-03-27T07:35:15+0530 lvl=info msg=" - cgroup layout: hybrid" 
t=2020-03-27T07:35:15+0530 lvl=warn msg=" - Couldn't find the CGroup blkio.weight, I/O weight limits will be ignored" 
t=2020-03-27T07:35:15+0530 lvl=info msg=" - shiftfs support: disabled" 
t=2020-03-27T07:35:15+0530 lvl=info msg="Initializing local database" 
t=2020-03-27T07:35:16+0530 lvl=info msg="Starting /dev/lxd handler:" 
t=2020-03-27T07:35:16+0530 lvl=info msg=" - binding devlxd socket" socket=/var/snap/lxd/common/lxd/devlxd/sock
t=2020-03-27T07:35:16+0530 lvl=info msg="REST API daemon:" 
t=2020-03-27T07:35:16+0530 lvl=info msg=" - binding Unix socket" inherited=true socket=/var/snap/lxd/common/lxd/unix.socket
t=2020-03-27T07:35:16+0530 lvl=info msg=" - binding TCP socket" socket=[::]:8443
t=2020-03-27T07:35:16+0530 lvl=info msg="Initializing global database" 
t=2020-03-27T07:35:21+0530 lvl=info msg="Firewall loaded driver \"nftables\"" 
t=2020-03-27T07:35:21+0530 lvl=info msg="Initializing storage pools" 
t=2020-03-27T07:35:22+0530 lvl=info msg="Initializing daemon storage mounts" 
t=2020-03-27T07:35:22+0530 lvl=info msg="Initializing networks" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Pruning leftover image files" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Done pruning leftover image files" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Loading daemon configuration" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Started seccomp handler" path=/var/snap/lxd/common/lxd/seccomp.socket
t=2020-03-27T07:35:23+0530 lvl=info msg="Pruning expired images" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Done pruning expired images" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Pruning expired instance backups" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Done pruning expired instance backups" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Expiring log files" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Done expiring log files" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Updating instance types" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Done updating instance types" 
t=2020-03-27T07:35:23+0530 lvl=info msg="Starting container" action=start created=2019-01-21T06:49:25+0530 ephemeral=false name=dbserver project=default stateful=false used=2020-03-15T19:06:19+0530

When i issue ‘lxd exec zmvm bash’. lxd monitor reports the following,

location: none
metadata:
  context:
    ip: '@'
    method: GET
    url: /1.0
    user: ""
  level: dbug
  message: Handling
timestamp: "2020-03-27T08:06:37.165621984+05:30"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: GET
    url: /1.0/events
    user: ""
  level: dbug
  message: Handling
timestamp: "2020-03-27T08:06:37.178675435+05:30"
type: logging


location: none
metadata:
  context: {}
  level: dbug
  message: 'New event listener: e84ffed1-f481-4f6d-a059-6a2dab505efa'
timestamp: "2020-03-27T08:06:37.179137671+05:30"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: POST
    url: /1.0/instances/zmvm/exec
    user: ""
  level: dbug
  message: Handling
timestamp: "2020-03-27T08:06:37.179956772+05:30"
type: logging


location: none
metadata:
  context: {}
  level: dbug
  message: 'forkcheckfile: Path doesn''t exist: No such file or directory'
timestamp: "2020-03-27T08:06:37.189149779+05:30"
type: logging


location: none
metadata:
  context: {}
  level: dbug
  message: 'New websocket Operation: 404ab451-9beb-4819-a406-54f7e101adf2'
timestamp: "2020-03-27T08:06:37.192862711+05:30"
type: logging


location: none
metadata:
  class: websocket
  created_at: "2020-03-27T08:06:37.18926203+05:30"
  description: Executing command
  err: ""
  id: 404ab451-9beb-4819-a406-54f7e101adf2
  location: none
  may_cancel: false
  metadata:
    command:
    - bash
    environment:
      HOME: /root
      LANG: C.UTF-8
      PATH: /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
      TERM: xterm-256color
      TZ: Asia/Kolkata
      USER: root
    fds:
      "0": 1709f74180ed4773fd59aaefc36bccb25202ed6dc60781924bb2602be320c617
      control: 455b6401d20092fd2641341f352f3ed3b4597debd35d9f940812ca3eccb70040
    interactive: true
  resources:
    containers:
    - /1.0/containers/zmvm
  status: Pending
  status_code: 105
  updated_at: "2020-03-27T08:06:37.18926203+05:30"
timestamp: "2020-03-27T08:06:37.193384991+05:30"
type: operation


location: none
metadata:
  context: {}
  level: dbug
  message: 'Started websocket operation: 404ab451-9beb-4819-a406-54f7e101adf2'
timestamp: "2020-03-27T08:06:37.193425564+05:30"
type: logging


location: none
metadata:
  class: websocket
  created_at: "2020-03-27T08:06:37.18926203+05:30"
  description: Executing command
  err: ""
  id: 404ab451-9beb-4819-a406-54f7e101adf2
  location: none
  may_cancel: false
  metadata:
    command:
    - bash
    environment:
      HOME: /root
      LANG: C.UTF-8
      PATH: /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
      TERM: xterm-256color
      TZ: Asia/Kolkata
      USER: root
    fds:
      "0": 1709f74180ed4773fd59aaefc36bccb25202ed6dc60781924bb2602be320c617
      control: 455b6401d20092fd2641341f352f3ed3b4597debd35d9f940812ca3eccb70040
    interactive: true
  resources:
    containers:
    - /1.0/containers/zmvm
  status: Running
  status_code: 103
  updated_at: "2020-03-27T08:06:37.18926203+05:30"
timestamp: "2020-03-27T08:06:37.193717743+05:30"
type: operation


location: none
metadata:
  context:
    ip: '@'
    method: GET
    url: /1.0/operations/404ab451-9beb-4819-a406-54f7e101adf2/websocket?secret=455b6401d20092fd2641341f352f3ed3b4597debd35d9f940812ca3eccb70040
    user: ""
  level: dbug
  message: Handling
timestamp: "2020-03-27T08:06:37.19550283+05:30"
type: logging


location: none
metadata:
  context: {}
  level: dbug
  message: 'Connected websocket Operation: 404ab451-9beb-4819-a406-54f7e101adf2'
timestamp: "2020-03-27T08:06:37.19554155+05:30"
type: logging


location: none
metadata:
  context: {}
  level: dbug
  message: 'Handled websocket Operation: 404ab451-9beb-4819-a406-54f7e101adf2'
timestamp: "2020-03-27T08:06:37.197593669+05:30"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: GET
    url: /1.0/operations/404ab451-9beb-4819-a406-54f7e101adf2/websocket?secret=1709f74180ed4773fd59aaefc36bccb25202ed6dc60781924bb2602be320c617
    user: ""
  level: dbug
  message: Handling
timestamp: "2020-03-27T08:06:37.200110694+05:30"
type: logging


location: none
metadata:
  context: {}
  level: dbug
  message: 'Connected websocket Operation: 404ab451-9beb-4819-a406-54f7e101adf2'
timestamp: "2020-03-27T08:06:37.200146764+05:30"
type: logging


location: none
metadata:
  context: {}
  level: dbug
  message: 'Handled websocket Operation: 404ab451-9beb-4819-a406-54f7e101adf2'
timestamp: "2020-03-27T08:06:37.200473906+05:30"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: GET
    url: /1.0/operations/404ab451-9beb-4819-a406-54f7e101adf2
    user: ""
  level: dbug
  message: Handling
timestamp: "2020-03-27T08:06:37.20147789+05:30"
type: logging

Thanks

2

I think I get the same issue, on Ubuntu 20.04 and LXD 3.23.

What does /var/snap/lxd/common/lxd/logs/zmvm/lxc.log show?

3

I get this,

# cat /var/snap/lxd/common/lxd/logs/zmvm/lxc.log
lxc zmvm 20200327020622.258 ERROR    cgfsng - cgroups/cgfsng.c:mkdir_eexist_on_last:1136 - File exists - Failed to create directory "/sys/fs/cgroup/cpuset//lxc.monitor.zmvm"
lxc zmvm 20200327020622.260 ERROR    cgfsng - cgroups/cgfsng.c:mkdir_eexist_on_last:1136 - File exists - Failed to create directory "/sys/fs/cgroup/cpuset//lxc.payload.zmvm"
lxc zmvm 20200327020622.265 WARN     cgfsng - cgroups/cgfsng.c:fchowmodat:1448 - No such file or directory - Failed to fchownat(17, memory.oom.group, 1000000000, 0, AT_EMPTY_PATH | AT_SYMLINK_NOFOLLOW )
4

I believe we have isolated the bad commit which caused this (ironically, a bugfix that was meant to fix exec issues for a bunch of users…). I have a snap building in the candidate channel now. Roll-out scheduled for an hour from now, assuming our tests confirm this did the trick.

5

I can confirm that the fix works as intended.

6

The fix has now been pushed to the stable channel.
A snap refresh will get you fixed.

2 Likes
7

Thanks, that fixed it.

8

Fixed here as well, thanks!