TestMultiContainerEvent test failed

Description

When running bazel test //runsc/container:container_test --test_filter=TestMultiContainerEvent --cache_test_results=no for sever times, it always failed with following message:

--- FAIL: TestMultiContainerEvent (0.77s)
    multi_container_test.go:1921: Running containerd test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK
    multi_container_test.go:1921: Running containerd test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG
    multi_container_test.go:1921: Running containerd test-container-TYRWTLSFZLLSLDFBCJRDI5RNJC3JK3LG
    multi_container_test.go:1966: Running container should report nonzero CPU usage, but got 0
    multi_container_test.go:1969: Expected container test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK to use more than 0 ns of CPU, but used 0
    multi_container_test.go:1971: Container test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK usage: 0
    multi_container_test.go:1971: Container test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG usage: 90000000

Steps to reproduce I use following shell script to detect error

#!/bin/bash
while true;do
bazel test //runsc/container:container_test --test_filter=TestMultiContainerEvent --cache_test_results=no --test_output=streamed > report 2>&1
fail=`cat report|grep FAIL|wc -l`
if [ $fail -ne 0 ];then
        break
fi
done

Environment

Please include the following details of your environment:

uname -a Linux entos-x86-desktop-03 5.9.0
git describe (if built from source) release-20210419.0-11-g07a78ecb2

runsc debug logs (if available)

exec ${PAGER:-/usr/bin/less} "$0" || exit 1
Executing tests from //runsc/container:container_test
-----------------------------------------------------------------------------
D0422 07:09:36.865066      23 container.go:522] Wait on container, cid: test-container-TYRWTLSFZLLSLDFBCJRDI5RNJC3JK3LG
D0422 07:09:36.865073      23 sandbox.go:794] Waiting for container "test-container-TYRWTLSFZLLSLDFBCJRDI5RNJC3JK3LG" in sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.865082      23 sandbox.go:367] Connecting to sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.865102      23 urpc.go:551] urpc: successfully marshalled 90 bytes.
Haolin 16: systime: 0sD0422 07:09:36.872287      23 urpc.go:594] urpc: unmarshal success.
D0422 07:09:36.872315      23 sandbox.go:299] Getting processes for container "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK" in sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.872323      23 sandbox.go:367] Connecting to sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.872341      23 urpc.go:551] urpc: successfully marshalled 95 bytes.
Haolin 16: systime: 0sHaolin 16: systime: 0sD0422 07:09:36.872587      23 urpc.go:594] urpc: unmarshal success.
D0422 07:09:36.872605      23 sandbox.go:299] Getting processes for container "test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG" in sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.872612      23 sandbox.go:367] Connecting to sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.872626      23 urpc.go:551] urpc: successfully marshalled 95 bytes.
Haolin 16: systime: 20msHaolin 16: systime: 20msD0422 07:09:36.872802      23 urpc.go:594] urpc: unmarshal success.
D0422 07:09:36.872820      23 container.go:494] Getting events for container, cid: test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK
D0422 07:09:36.872825      23 sandbox.go:349] Getting events for container "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK" in sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.872829      23 sandbox.go:367] Connecting to sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.872847      23 urpc.go:551] urpc: successfully marshalled 46 bytes.
Haolin 16: systime: 0sHaolin 16: systime: 0sHaolin 16: systime: 20msHaolin 16: systime: 20msD0422 07:09:36.873190      23 urpc.go:594] urpc: unmarshal success.
W0422 07:09:36.873206      23 container.go:1135] event.ContainerUsage: map[test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK:0 test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG:90000000]
D0422 07:09:36.873475      23 cgroup.go:485] Haolin2: cgroup &{user.slice map[blkio:user.slice cpu:user.slice cpuacct:user.slice cpuset:. devices:user.slice freezer:. hugetlb:. memory:user.slice/user-0.slice/session-1246.scope net_cls:. net_prio:. perf_event:. pids:user.slice/user-0.slice/session-1246.scope rdma:. systemd:user.slice/user-0.slice/session-1246.scope] map[]}
W0422 07:09:36.873504      23 container.go:1157] events: failed when getting cgroup CPU usage for container: open /sys/fs/cgroup/cpuacct/user.slice/user.slice/cpuacct.usage: no such file or directory
D0422 07:09:36.873522      23 container.go:494] Getting events for container, cid: test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG
D0422 07:09:36.873526      23 sandbox.go:349] Getting events for container "test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG" in sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.873530      23 sandbox.go:367] Connecting to sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.873545      23 urpc.go:551] urpc: successfully marshalled 46 bytes.
Haolin 16: systime: 0sHaolin 16: systime: 0sHaolin 16: systime: 20msHaolin 16: systime: 20msD0422 07:09:36.873721      23 urpc.go:594] urpc: unmarshal success.
W0422 07:09:36.873737      23 container.go:1135] event.ContainerUsage: map[test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK:0 test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG:90000000]
D0422 07:09:36.874058      23 cgroup.go:485] Haolin2: cgroup &{user.slice map[blkio:user.slice cpu:user.slice cpuacct:user.slice cpuset:. devices:user.slice freezer:. hugetlb:. memory:user.slice/user-0.slice/session-1246.scope net_cls:. net_prio:. perf_event:. pids:user.slice/user-0.slice/session-1246.scope rdma:. systemd:user.slice/user-0.slice/session-1246.scope] map[]}
W0422 07:09:36.874078      23 container.go:1157] events: failed when getting cgroup CPU usage for container: open /sys/fs/cgroup/cpuacct/user.slice/user.slice/cpuacct.usage: no such file or directory
D0422 07:09:36.874090      23 container.go:672] Destroy container, cid: test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG
D0422 07:09:36.874100      23 container.go:757] Destroying container, cid: test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG
D0422 07:09:36.874105      23 sandbox.go:1133] Destroying container, cid: test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG, sandbox: test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK
D0422 07:09:36.874108      23 sandbox.go:367] Connecting to sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.874139      23 urpc.go:551] urpc: successfully marshalled 93 bytes.
Haolin 16: systime: 20msD0422 07:09:36.875617      23 urpc.go:594] urpc: unmarshal success.
D0422 07:09:36.875633      23 container.go:771] Killing gofer for container, cid: test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG, PID: 72
D0422 07:09:36.976770      23 state_file.go:52] Load container, rootDir: "/root/.cache/bazel/_bazel_root/534e3258f2fed55c3df105f2417572d2/sandbox/linux-sandbox/131/execroot/__main__/_tmp/efb1ff805b58117bfcc632db98d5b5a6/containers894449564", id: {SandboxID:test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK ContainerID:test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK}, opts: {Exact:true SkipCheck:true}
D0422 07:09:36.977446      23 state_file.go:52] Load container, rootDir: "/root/.cache/bazel/_bazel_root/534e3258f2fed55c3df105f2417572d2/sandbox/linux-sandbox/131/execroot/__main__/_tmp/efb1ff805b58117bfcc632db98d5b5a6/containers894449564", id: {SandboxID:test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK ContainerID:test-container-TYRWTLSFZLLSLDFBCJRDI5RNJC3JK3LG}, opts: {Exact:true SkipCheck:true}
D0422 07:09:36.978070      23 container.go:494] Getting events for container, cid: test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG
D0422 07:09:36.978136      23 container.go:494] Getting events for container, cid: test-container-TYRWTLSFZLLSLDFBCJRDI5RNJC3JK3LG
D0422 07:09:36.978172      23 container.go:672] Destroy container, cid: test-container-TYRWTLSFZLLSLDFBCJRDI5RNJC3JK3LG
D0422 07:09:36.978227      23 container.go:757] Destroying container, cid: test-container-TYRWTLSFZLLSLDFBCJRDI5RNJC3JK3LG
D0422 07:09:36.978247      23 sandbox.go:1133] Destroying container, cid: test-container-TYRWTLSFZLLSLDFBCJRDI5RNJC3JK3LG, sandbox: test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK
D0422 07:09:36.978273      23 sandbox.go:367] Connecting to sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:36.978366      23 urpc.go:551] urpc: successfully marshalled 93 bytes.
D0422 07:09:36.979039      23 urpc.go:594] urpc: unmarshal success.
D0422 07:09:36.979121      23 container.go:771] Killing gofer for container, cid: test-container-TYRWTLSFZLLSLDFBCJRDI5RNJC3JK3LG, PID: 102
D0422 07:09:37.080476      23 state_file.go:52] Load container, rootDir: "/root/.cache/bazel/_bazel_root/534e3258f2fed55c3df105f2417572d2/sandbox/linux-sandbox/131/execroot/__main__/_tmp/efb1ff805b58117bfcc632db98d5b5a6/containers894449564", id: {SandboxID:test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK ContainerID:test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK}, opts: {Exact:true SkipCheck:true}
D0422 07:09:37.081496      23 container.go:672] Destroy container, cid: test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG
D0422 07:09:37.081833      23 container.go:672] Destroy container, cid: test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK
D0422 07:09:37.081885      23 container.go:757] Destroying container, cid: test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK
D0422 07:09:37.081907      23 sandbox.go:1129] Destroying root container by destroying sandbox, cid: test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK
D0422 07:09:37.081925      23 sandbox.go:869] Destroy sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:37.081944      23 sandbox.go:871] Killing sandbox "test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK"
D0422 07:09:37.183576      23 container.go:771] Killing gofer for container, cid: test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK, PID: 29
--- FAIL: TestMultiContainerEvent (0.77s)
multi_container_test.go:1921: Running containerd test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK
multi_container_test.go:1921: Running containerd test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG
multi_container_test.go:1921: Running containerd test-container-TYRWTLSFZLLSLDFBCJRDI5RNJC3JK3LG
multi_container_test.go:1966: Running container should report nonzero CPU usage, but got 0
multi_container_test.go:1969: Expected container test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK to use more than 0 ns of CPU, but used 0
multi_container_test.go:1971: Container test-container-IJNV6LZ2XITHL3PAWVVTPG7ISLKGJVXK usage: 0
multi_container_test.go:1971: Container test-container-N3S4P2NHO3HF6HZBB7MLQSRCDBRMFUHG usage: 90000000
FAIL

As there is a message in the log W0422 07:09:36.874078 23 container.go:1157] events: failed when getting cgroup CPU usage for container: open /sys/fs/cgroup/cpuacct/user.slice/user.slice/cpuacct.usage: no such file or directory The user.slice repeated twice in the path. I think this may be related to the commit 5f7bf31526.

Would you like to take a look when you have time? @kevinGC

google / gvisor

TestMultiContainerEvent test failed #5875