Runc init process step on DISK Sleep Status When freezen cgroup

[gaopeiliang]

we upgrade docker-ce version to 20:10 from 19.3, And now docker component version:

Client: Docker Engine - Community
 Version:           20.10.1
 API version:       1.41
 Go version:        go1.13.15
 Git commit:        831ebea
 Built:             Tue Dec 15 04:35:01 2020
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.1
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.13.15
  Git commit:       f001486
  Built:            Tue Dec 15 04:32:57 2020
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.4.3
  GitCommit:        269548fa27e0089a8b8278fc4fc781d7f65a939b
 runc:
  Version:          1.0.0-rc92
  GitCommit:        ff819c7e9184c13b7c2607fe6c30ae19403a7aff
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

when Kubernetes terminal POD , we found container process step into DISK Sleep status ,,,, docker inspect container hang forever ,, kubelet pleg not healthy , kubelet not ready ......

when we ps container process .... we found runc init process also DISK Sleep ....

root     15758 57587  0 16:39 ?        00:00:00 runc --root /var/run/docker/runtime-runc/moby --log /run/containerd/io.containerd.runtime.v2.task/moby/452a153f1775d37f5813c1b71ff46df6e0da76ce5e8450d3df46d1de3cc97b2c/log.json --log-format json --systemd-cgroup exec --process /tmp/runc-process627966115 --detach --pid-file /run/containerd/io.containerd.runtime.v2.task/moby/452a153f1775d37f5813c1b71ff46df6e0da76ce5e8450d3df46d1de3cc97b2c/27e5850550ae06545bde2abb0470316e95938c54ad673bb9b1e0686129d10ae1.pid 452a153f1775d37f5813c1b71ff46df6e0da76ce5e8450d3df46d1de3cc97b2c
root     15795 15758  0 16:39 ?        00:00:00 runc init
root     15801 57587  4 16:39 ?        00:12:50 runc --root /var/run/docker/runtime-runc/moby --log /run/containerd/io.containerd.runtime.v2.task/moby/452a153f1775d37f5813c1b71ff46df6e0da76ce5e8450d3df46d1de3cc97b2c/log.json --log-format json --systemd-cgroup update --resources - 452a153f1775d37f5813c1b71ff46df6e0da76ce5e8450d3df46d1de3cc97b2c

# runc init process step in "D" status...
 
root@bigo:/home/xyz# cat /proc/15795/status
Name:   runc:[2:INIT]
Umask:  0022
State:  D (disk sleep)
Tgid:   15795
Ngid:   0
Pid:    15795
PPid:   15758
TracerPid:      0
Uid:    0       0       0       0
Gid:    0       0       0       0
FDSize: 64
Groups:  
NStgid: 15795   230
NSpid:  15795   230
NSpgid: 15795   230
NSsid:  15795   230
VmPeak:   279548 kB
VmSize:   230660 kB
VmLck:         0 kB
VmPin:         0 kB
VmHWM:     14876 kB
VmRSS:     14876 kB
RssAnon:            9064 kB
RssFile:            5812 kB
RssShmem:              0 kB

[gaopeiliang]

runc init parent process maybe runc exec xxx yyy 15758 is in sleep status .....

there another process about runc update resource 15801 si in sleep status ......

we strace 15801 .... it is wait cgroup freezer change "FREEZING" to last status ....

newfstatat(AT_FDCWD, "/sys/fs/cgroup/freezer/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod6ee54f7c_8b7b_49a6_ad29_5fa0e1d953b3.slice/docker-452a153f1775d37f5813c1b71ff46df6e0da76ce5e8450d3df46d1de3cc97b2c.scope/freezer.state", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
openat(AT_FDCWD, "/sys/fs/cgroup/freezer/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod6ee54f7c_8b7b_49a6_ad29_5fa0e1d953b3.slice/docker-452a153f1775d37f5813c1b71ff46df6e0da76ce5e8450d3df46d1de3cc97b2c.scope/freezer.state", O_RDONLY|O_CLOEXEC) = 7
epoll_ctl(4, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=3228278120, u64=139778643959144}}) = 0
fcntl(7, F_GETFL)                       = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
fstat(7, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
read(7, "FREEZING\n", 512)              = 9
read(7, "", 1527)                       = 0
epoll_ctl(4, EPOLL_CTL_DEL, 7, 0xc0005647dc) = 0
close(7)                                = 0
futex(0xc0000432c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x5616715d98e0, FUTEX_WAIT_PRIVATE, 0, {0, 975302}) = -1 ETIMEDOUT (Connection timed out)
futex(0x5616715d5b10, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x5616715d5a10, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc0000432c8, FUTEX_WAKE_PRIVATE, 1) = 1
newfstatat(AT_FDCWD, "/sys/fs/cgroup/freezer/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod6ee54f7c_8b7b_49a6_ad29_5fa0e1d953b3.slice/docker-452a153f1775d37f5813c1b71ff46df6e0da76ce5e8450d3df46d1de3cc97b2c.scope/freezer.state", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
openat(AT_FDCWD, "/sys/fs/cgroup/freezer/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod6ee54f7c_8b7b_49a6_ad29_5fa0e1d953b3.slice/docker-452a153f1775d37f5813c1b71ff46df6e0da76ce5e8450d3df46d1de3cc97b2c.scope/freezer.state", O_RDONLY|O_CLOEXEC) = 7
epoll_ctl(4, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=3228278120, u64=139778643959144}}) = 0
fcntl(7, F_GETFL)                       = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
fstat(7, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
read(7, "FREEZING\n", 512)              = 9
read(7, "", 1527)                       = 0
epoll_ctl(4, EPOLL_CTL_DEL, 7, 0xc0005647dc) = 0
close(7)                                = 0
futex(0xc0000432c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x5616715d98e0, FUTEX_WAIT_PRIVATE, 0, {0, 975585}) = -1 ETIMEDOUT (Connection timed out)
futex(0xc0000432c8, FUTEX_WAKE_PRIVATE, 1) = 1
newfstatat(AT_FDCWD, "/sys/fs/cgroup/freezer/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod6ee54f7c_8b7b_49a6_ad29_5fa0e1d953b3.slice/docker-452a153f1775d37f5813c1b71ff46df6e0da76ce5e8450d3df46d1de3cc97b2c.scope/freezer.state", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
openat(AT_FDCWD, "/sys/fs/cgroup/freezer/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod6ee54f7c_8b7b_49a6_ad29_5fa0e1d953b3.slice/docker-452a153f1775d37f5813c1b71ff46df6e0da76ce5e8450d3df46d1de3cc97b2c.scope/freezer.state", O_RDONLY|O_CLOEXEC) = 7
epoll_ctl(4, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=3228278120, u64=139778643959144}}) = 0
fcntl(7, F_GETFL)                       = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
fstat(7, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
read(7, "FREEZING\n", 512)              = 9
read(7, "", 1527)                       = 0
epoll_ctl(4, EPOLL_CTL_DEL, 7, 0xc0005647dc) = 0
close(7)       

[gaopeiliang]

exec init + set cgroup freeze will make cgroup step on FREEZING status

as code note said ,,, the final status really never come,, loop run infinitely ....

func (s *FreezerGroup) Set(path string, cgroup *configs.Cgroup) error {
	switch cgroup.Resources.Freezer {
	case configs.Frozen, configs.Thawed:
		for {
			// In case this loop does not exit because it doesn't get the expected
			// state, let's write again this state, hoping it's going to be properly
			// set this time. Otherwise, this loop could run infinitely, waiting for
			// a state change that would never happen.
			if err := fscommon.WriteFile(path, "freezer.state", string(cgroup.Resources.Freezer)); err != nil {
				return err
			}

			state, err := s.GetState(path)
			if err != nil {
				return err
			}
			if state == cgroup.Resources.Freezer {
				break
			}

			time.Sleep(1 * time.Millisecond)
		}
	case configs.Undefined:
		return nil
	default:
		return fmt.Errorf("Invalid argument '%s' to freezer.state", string(cgroup.Resources.Freezer))
	}

	return nil
}

[gaopeiliang]

#2767

[gaopeiliang]

Linux kernel 4.19.160-0419160-generic
Linux kernel 4.9.70-040970-generic

[kolyshkin]

If you can come up with a repro that does not involve docker, kubernetes etc. that'd be great.

[gaopeiliang]

as code note said ,,, the final status really never come,, loop run infinitely ....

we also should reset the status ,,, not block getState forever.....

func (s *FreezerGroup) Set(path string, cgroup *configs.Cgroup) error {
	switch cgroup.Resources.Freezer {
	case configs.Frozen, configs.Thawed:
		for {
			// In case this loop does not exit because it doesn't get the expected
			// state, let's write again this state, hoping it's going to be properly
			// set this time. Otherwise, this loop could run infinitely, waiting for
			// a state change that would never happen.
			if err := fscommon.WriteFile(path, "freezer.state", string(cgroup.Resources.Freezer)); err != nil {
				return err
			}

			state, err := s.GetState(path)
			if err != nil {
				return err
			}
			if state == cgroup.Resources.Freezer {
				break
			}

			time.Sleep(1 * time.Millisecond)
		}
	case configs.Undefined:
		return nil
	default:
		return fmt.Errorf("Invalid argument '%s' to freezer.state", string(cgroup.Resources.Freezer))
	}

	return nil
}

[gaopeiliang]

we also found an description about this on "Red Hat bugzilla",

https://bugzilla.redhat.com/show_bug.cgi?id=1903228

I think there also meet this issues .....

[gaopeiliang]

we used runc rc-10 with docker 19 ,,, and never hit "DISK Sleep" until we upgrade to docker20 with runc rc92 , we try to replace runc rc92 to rc-10 , and nothing happen ,,,,

I think rc92 update command add freezen cgroup step ,, increase the probability

[niuyueyang1996]

i write freezer.state file and use runc exec to reproduce the failure

package main

import (
	"flag"
	"fmt"
	"github.com/cyphar/filepath-securejoin"
	"github.com/pkg/errors"
	"golang.org/x/sys/unix"
	"io/ioutil"
	"log"
	"math/rand"
	"os"
	"os/exec"
	"strings"
	"time"
)

func main() {
	var path string
	var cid string
	flag.StringVar(&path, "p", "", "")
	flag.StringVar(&cid, "c", "", "")
	flag.Parse()
	if path == "" || cid == "" {
		panic("path is empty")
	}
	for i := 0; i < 15; i++ {
		go func() {
			for {
				start := time.Now()
				cmd := exec.Command("bash", "exec.sh", cid)
				cmd.Stdout = os.Stdout
				err := cmd.Run()
				if err != nil {
					log.Print(err)
				}
				fmt.Println(time.Now().Sub(start))
				num := rand.Intn(100)
				time.Sleep(time.Duration(num) * time.Millisecond)
			}
		}()
	}
	for i := 0; i < 4; i++ {
		for {
			err := freezeAndThawed(path)
			if err != nil {
				log.Printf("freeze and thawed %v", err)
			} else {
				log.Printf("freeze and thawed success")
			}
			time.Sleep(time.Duration(rand.Intn(400)+200) * time.Millisecond)
		}
	}

}

func freezeAndThawed(path string) (err error) {
	err = freezeWithTimeout(path, string(Frozen))
	if err != nil {
		return err
	}
	err = freezeWithTimeout(path, string(Thawed))
	if err != nil {
		return err
	}
	err = freezeWithTimeout(path, string(Thawed))
	if err != nil {
		return err
	}
	return err
}

func freezeWithTimeout(path, freezer string) (err error) {
	ch := make(chan error)
	go func() {
		ch <- freeze(path, freezer)
	}()
	for {
		select {
		case <-time.After(10 * time.Second):
			log.Printf("time out to set freeze %v %v", path, freezer)
		case err := <-ch:
			log.Printf("set path %v,%v end %v", path, freezer, err)
			return err
		}
	}
}

type FreezerState string

const (
	Undefined FreezerState = ""
	Frozen    FreezerState = "FROZEN"
	Thawed    FreezerState = "THAWED"
)

func getFreezeWithTimeout(path string) (state FreezerState, err error) {
	type r struct {
		state FreezerState
		err   error
	}
	ch := make(chan r)
	go func() {
		state, err := getFreeze(path)
		ch <- r{state, err}
	}()
	for {
		select {
		case <-time.After(10 * time.Second):
			log.Printf("time out to get freeze %v", path)
		case r := <-ch:
			log.Printf("get from path %v,%v %v", path, r.state, r.err)
			return r.state, r.err
		}
	}
}
func getFreeze(path string) (state FreezerState, err error) {
	for {
		state, err := ReadFile(path, "freezer.state")
		if err != nil {
			// If the kernel is too old, then we just treat the freezer as
			// being in an "undefined" state.
			if os.IsNotExist(err) || errors.Is(err, unix.ENODEV) {
				err = nil
			}
			return Undefined, err
		}
		switch strings.TrimSpace(state) {
		case "THAWED":
			return Thawed, nil
		case "FROZEN":
			return Frozen, nil
		case "FREEZING":
			// Make sure we get a stable freezer state, so retry if the cgroup
			// is still undergoing freezing. This should be a temporary delay.
			time.Sleep(1 * time.Millisecond)
			continue
		default:
			return Undefined, fmt.Errorf("unknown freezer.state %q", state)
		}
	}
}
func freeze(path string, freezer string) (err error) {
	for {
		// In case this loop does not exit because it doesn't get the expected
		// state, let's write again this state, hoping it's going to be properly
		// set this time. Otherwise, this loop could run infinitely, waiting for
		// a state change that would never happen.
		if err := WriteFile(path, "freezer.state", freezer); err != nil {
			return err
		}
		state, err := getFreezeWithTimeout(path)
		if err != nil {
			return err
		}
		if strings.TrimSpace(string(state)) == freezer {
			break
		}

		time.Sleep(1 * time.Millisecond)
	}
	return nil
}
func WriteFile(dir, file, data string) error {
	if dir == "" {
		return errors.Errorf("no directory specified for %s", file)
	}
	path, err := securejoin.SecureJoin(dir, file)
	if err != nil {
		return err
	}
	if err := ioutil.WriteFile(path, []byte(data), 0700); err != nil {
		return errors.Wrapf(err, "failed to write %q to %q", data, path)
	}
	return nil
}
func ReadFile(dir, file string) (string, error) {
	if dir == "" {
		return "", errors.Errorf("no directory specified for %s", file)
	}
	path, err := securejoin.SecureJoin(dir, file)
	if err != nil {
		return "", err
	}
	data, err := ioutil.ReadFile(path)
	return string(data), err
}

exec.sh

runc --root=/var/run/docker/runtime-runc/moby/ exec $1 stat /data

[niuyueyang1996]

when exec execute concurrently with freezen will reproduce the failure
we hope getState and freeze can exit with timeout

[kolyshkin]

@niuyueyang1996 @gaopeiliang thanks, reproduced locally (on cgroup v1 -- apparently v2 is not vulnerable), Ubuntu 20.04, kernel 5.4.0-42-generic.

[kolyshkin]

Simplified repro in bash

# Run exec and pause/resume in parallel
(
	while :; do
		$RUNC exec $CID printf .
	done
) &
PID_EXEC=$!

(
	while :; do
		$RUNC pause $CID && $RUNC resume $CID && date
	done
) &
PID_FUF=$!

sleep 1m
kill -9 $PID_FUF
kill -9 $PID_EXEC

runc exec $CID true && echo "success"

Usually 10s or so is enough to repro.

When runc init is stuck in D state, here's how it looks like:

root@ubu2004:/home/kir/git/runc# cat /proc/337830/stack 
[<0>] __refrigerator+0x50/0x150
[<0>] get_signal+0x86f/0x890
[<0>] do_signal+0x34/0x6c0
[<0>] exit_to_usermode_loop+0xbf/0x160
[<0>] do_syscall_64+0x163/0x190
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9

[kolyshkin]

Since the reporter saw it during the concurrent use of runc update and runc exec, it looks like a regression caused by commit b810da1 (PR #2391). In short, when system cgroup driver is used, it freezes the container on every runc update for the sake of setting systemd unit device properties (even if they are not set/changed) // cc @cyphar