Firecracker randomly failing with kata-runtime

[GabyCT]

These last days, I have seen the Firecracker CI fail randomly, specially at the CRI-O tests, here it is an example of that

09:23:07 ++ time bats --jobs 1 --tap ctr.bats
09:23:07 1..46
09:23:31 ok 1 ctr not found correct error message
09:24:03 ok 2 ctr termination reason Completed
09:24:35 ok 3 ctr termination reason Error
09:25:29 not ok 4 ulimits
09:25:29 # (in test file ctr.bats, line 72)
09:25:29 #   `[ "$status" -eq 0 ]' failed
09:25:29 # time="2020-01-14T15:24:36Z" level=error msg="File descriptor 3 (pipe:[3025794]) leaked on pvdisplay invocation. Parent PID 92042: /tmp/jenkins/workspace/kata-con\nFile descriptor 6 (/dev/mapper/control) leaked on pvdisplay invocation. Parent PID 92042: /tmp/jenkins/workspace/kata-con\n  Failed to find physical volume \"/dev/sdb\".\n" error="exit status 5"
09:25:29 # 0
09:25:29 # time="2020-01-14 15:24:54.552100894Z" level=debug msg="found valid runtime \"runc\" for runtime_path \"/usr/local/bin/kata-runtime\"" file="config/config.go:803"
09:25:29 # time="2020-01-14 15:24:54.552233197Z" level=info msg="using conmon executable \"/usr/local/bin/conmon\"" file="config/config.go:734"
09:25:29 # time="2020-01-14 15:24:54.552953213Z" level=debug msg="[graphdriver] trying provided driver \"devicemapper\"" file="drivers/driver.go:244"
09:25:29 # time="2020-01-14 15:24:54.554572448Z" level=debug msg="devicemapper: kernel dm driver version is 4.39.0" file="devmapper/deviceset.go:1499"
09:25:29 # time="2020-01-14 15:24:54.554766752Z" level=debug msg="Setting dm.thinpooldev to \"storage-thinpool\"" file="devmapper/deviceset.go:1732" storage-driver=devicemapper
09:25:29 # time="2020-01-14 15:24:54.554839554Z" level=debug msg="devmapper: Generated prefix: container-8:1-274236" file="devmapper/deviceset.go:1747"
09:25:29 # time="2020-01-14 15:24:54.554896955Z" level=debug msg="devmapper: Checking for existence of the pool storage-thinpool" file="devmapper/deviceset.go:1095"
09:25:29 # time="2020-01-14 15:24:54.555673072Z" level=debug msg="devmapper: loadDeviceFilesOnStart()" file="devmapper/deviceset.go:457"
09:25:29 # time="2020-01-14 15:24:54.556256684Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/01d6f430ddfdf1203b505fbb03c6479802a3366609d5e0231a30f85f412f873d" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.556493489Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/0314be9edf00a925d59f9b88c9d8ccb34447ab677078874d8c14e7a6816e21e1" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.556652693Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/18a9c5dd4fc33b1b7f3e54d30fee0c94a9b0f280ba595a928508b8f79c925c66" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.556818396Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/1a1edaafa91f809f5f7dd6367d47b4f36d7dced734a9628350e0fef133c68379" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.556998400Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/389ba2153eeb8a200660313dcd6f1f4a84ec8d80ec7c651100791b2c80dd121d" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.557219705Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/3fc666989c1d08d3ff91e75f335d898f525648e68e0264c50489ffe85b93eb76" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.557294907Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/55e69498dbee26b17f32a9d6f122097319df6e9ec515ca44b4146848923a4a9f" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.557361308Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/78ca90b1d5f1c01b1eab2929d02268e2cceb00512929f6d71b30bf8b41a22944" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.557424510Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/ad54249f0bda53d7537a95c55e114dfe1218194a9af78cff031597476adb96ba" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.558365330Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/b0e4f203926e643573ffcdf7738dc79394cd4c208209cf359d697c29b4e14b94" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.558444032Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/base" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.558510033Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/c00cd482af6ac6289450241b4a1c3dcfc4d91a0b1f9ac8c405ca5c8f3ff5319e" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.558574635Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/cd7100a72410606589a54b932cabd804a17f9ae5b42a1882bd56d263e02b6215" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.558636936Z" level=debug msg="devmapper: Skipping file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/deviceset-metadata" file="devmapper/deviceset.go:431"
09:25:29 # time="2020-01-14 15:24:54.558683637Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/e154057080f406372ebecadc0bfb5ff8a7982a0d13823bab1be5b86926c6f860" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.558811440Z" level=debug msg="devmapper: Loading data for file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/e88b3f82283bc59d5e0df427c824e9f95557e661fcb0ea15fb0fb6f97760f9d9" file="devmapper/deviceset.go:440"
09:25:29 # time="2020-01-14 15:24:54.558877441Z" level=debug msg="devmapper: Skipping file /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/transaction-metadata" file="devmapper/deviceset.go:436"
09:25:29 # time="2020-01-14 15:24:54.558916642Z" level=debug msg="devmapper: loadDeviceFilesOnStart() END" file="devmapper/deviceset.go:474"
09:25:29 # time="2020-01-14 15:24:54.558952843Z" level=debug msg="devmapper: constructDeviceIDMap()" file="devmapper/deviceset.go:408"
09:25:29 # time="2020-01-14 15:24:54.558980743Z" level=debug msg="devmapper: Added deviceId=8 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559083746Z" level=debug msg="devmapper: Added deviceId=6 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559215348Z" level=debug msg="devmapper: Added deviceId=15 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559246549Z" level=debug msg="devmapper: Added deviceId=3 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559276050Z" level=debug msg="devmapper: Added deviceId=12 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559330151Z" level=debug msg="devmapper: Added deviceId=1 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559425553Z" level=debug msg="devmapper: Added deviceId=13 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559458354Z" level=debug msg="devmapper: Added deviceId=10 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559491054Z" level=debug msg="devmapper: Added deviceId=5 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559634458Z" level=debug msg="devmapper: Added deviceId=11 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559668658Z" level=debug msg="devmapper: Added deviceId=7 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559698759Z" level=debug msg="devmapper: Added deviceId=14 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559728360Z" level=debug msg="devmapper: Added deviceId=9 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559757560Z" level=debug msg="devmapper: Added deviceId=2 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559843062Z" level=debug msg="devmapper: Added deviceId=4 to DeviceIdMap" file="devmapper/deviceset.go:413"
09:25:29 # time="2020-01-14 15:24:54.559876663Z" level=debug msg="devmapper: constructDeviceIDMap() END" file="devmapper/deviceset.go:415"
09:25:29 # time="2020-01-14 15:24:54.560022166Z" level=debug msg="devmapper: activateDeviceIfNeeded()" file="devmapper/deviceset.go:518"
09:25:29 # time="2020-01-14 15:24:54.616960000Z" level=debug msg="devmapper: UUID for device: /dev/mapper/container-8:1-274236-base is:975c7874-e1d9-4ace-8345-bf75f8137040" file="devmapper/deviceset.go:983"
09:25:29 # time="2020-01-14 15:24:54.617035102Z" level=warning msg="devmapper: Base device already exists and has filesystem xfs on it. User specified filesystem  will be ignored." file="devmapper/deviceset.go:1031"
09:25:29 # time="2020-01-14 15:24:54.617067803Z" level=debug msg="devmapper: deactivateDevice START()" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:24:54.617128604Z" level=debug msg="devmapper: removeDevice START(container-8:1-274236-base)" file="devmapper/deviceset.go:2181"
09:25:29 # time="2020-01-14 15:24:54.662744593Z" level=debug msg="devmapper: removeDevice END(container-8:1-274236-base)" file="devmapper/deviceset.go:2200"
09:25:29 # time="2020-01-14 15:24:54.662821695Z" level=debug msg="devmapper: deactivateDevice END()" file="devmapper/deviceset.go:2172"
09:25:29 # time="2020-01-14 15:24:54.665822760Z" level=debug msg="reading hooks from /tmp/tmp.t9m5gZy5ct/hooks" file="hooks/read.go:65"
09:25:29 # time="2020-01-14 15:24:54.666464874Z" level=info msg="Found CNI network crionet (type=bridge) at /tmp/tmp.t9m5gZy5ct/cni/net.d/10-crio.conf" file="ocicni/ocicni.go:291"
09:25:29 # time="2020-01-14 15:24:54.671737488Z" level=info msg="no seccomp profile specified, using the internal default" file="server/server.go:411"
09:25:29 # time="2020-01-14 15:24:54.671842690Z" level=info msg="installing default apparmor profile: crio-default-1.16.0" file="server/server.go:417"
09:25:29 # time="2020-01-14 15:24:54.706126734Z" level=debug msg="Golang's threads limit set to 115110" file="server/server.go:310"
09:25:29 # time="2020-01-14 15:24:54.707387961Z" level=info msg="using host IPs: [10.0.0.8]" file="server/server.go:455"
09:25:29 # time="2020-01-14 15:24:54.707639366Z" level=debug msg="sandboxes: []" file="server/server.go:497"
09:25:29 # time="2020-01-14 15:24:54.707877572Z" level=debug msg="registered SIGHUP watcher for file \"/tmp/tmp.t9m5gZy5ct/crio.conf\"" file="server/server.go:773"
09:25:29 # time="2020-01-14 15:24:54.707990674Z" level=warning msg="unable to start config watcher for file \"/etc/containers/registries.conf\": stat /etc/containers/registries.conf: no such file or directory" file="server/server.go:508"
09:25:29 # time="2020-01-14 15:24:54.731826591Z" level=debug msg="monitoring \"/tmp/tmp.t9m5gZy5ct/hooks\" for hooks" file="hooks/monitor.go:43"
09:25:29 # time="2020-01-14 15:24:55.480972727Z" level=debug msg="request: &StatusRequest{Verbose:true,}" file="v1alpha2/api.pb.go:7978" id=4e076aac-927d-4359-aa45-a17d608e7cff
09:25:29 # time="2020-01-14 15:24:55.481206732Z" level=debug msg="response: &StatusResponse{Status:&RuntimeStatus{Conditions:[]*RuntimeCondition{&RuntimeCondition{Type:RuntimeReady,Status:true,Reason:,Message:,},&RuntimeCondition{Type:NetworkReady,Status:true,Reason:,Message:,},},},Info:map[string]string{},}" file="v1alpha2/api.pb.go:7978" id=4e076aac-927d-4359-aa45-a17d608e7cff
09:25:29 # time="2020-01-14 15:24:55.493049889Z" level=debug msg="request: &ImageStatusRequest{Image:&ImageSpec{Image:quay.io/crio/redis:alpine,},Verbose:true,}" file="v1alpha2/api.pb.go:8226" id=e7097608-39b6-44b9-a7e8-ec94f1224e73
09:25:29 # time="2020-01-14 15:24:55.493555799Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]quay.io/crio/redis:alpine\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.495997152Z" level=debug msg="response: &ImageStatusResponse{Image:&Image{Id:98bd7cfc43b8ef0ff130465e3d5427c0771002c2f35a6a9b62cb2d04602bed0a,RepoTags:[quay.io/crio/redis:alpine],RepoDigests:[quay.io/crio/redis@sha256:1780b5a5496189974b94eb2595d86731d7a0820e4beb8ea770974298a943ed55],Size_:28138628,Uid:nil,Username:,},Info:map[string]string{},}" file="v1alpha2/api.pb.go:8226" id=e7097608-39b6-44b9-a7e8-ec94f1224e73
09:25:29 # time="2020-01-14 15:24:55.507160594Z" level=debug msg="request: &ImageStatusRequest{Image:&ImageSpec{Image:quay.io/crio/redis:alpine,},Verbose:true,}" file="v1alpha2/api.pb.go:8226" id=c8596212-2e61-447c-8506-5f3c818257dc
09:25:29 # time="2020-01-14 15:24:55.507443100Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]quay.io/crio/redis:alpine\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.508816530Z" level=debug msg="response: &ImageStatusResponse{Image:&Image{Id:98bd7cfc43b8ef0ff130465e3d5427c0771002c2f35a6a9b62cb2d04602bed0a,RepoTags:[quay.io/crio/redis:alpine],RepoDigests:[quay.io/crio/redis@sha256:1780b5a5496189974b94eb2595d86731d7a0820e4beb8ea770974298a943ed55],Size_:28138628,Uid:nil,Username:,},Info:map[string]string{},}" file="v1alpha2/api.pb.go:8226" id=c8596212-2e61-447c-8506-5f3c818257dc
09:25:29 # time="2020-01-14 15:24:55.521312201Z" level=debug msg="request: &ImageStatusRequest{Image:&ImageSpec{Image:quay.io/crio/redis:alpine,},Verbose:true,}" file="v1alpha2/api.pb.go:8226" id=0019f81b-9398-41d4-93f3-08d199d2fd07
09:25:29 # time="2020-01-14 15:24:55.521583907Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]quay.io/crio/redis:alpine\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.523849456Z" level=debug msg="response: &ImageStatusResponse{Image:&Image{Id:98bd7cfc43b8ef0ff130465e3d5427c0771002c2f35a6a9b62cb2d04602bed0a,RepoTags:[quay.io/crio/redis:alpine],RepoDigests:[quay.io/crio/redis@sha256:1780b5a5496189974b94eb2595d86731d7a0820e4beb8ea770974298a943ed55],Size_:28138628,Uid:nil,Username:,},Info:map[string]string{},}" file="v1alpha2/api.pb.go:8226" id=0019f81b-9398-41d4-93f3-08d199d2fd07
09:25:29 # time="2020-01-14 15:24:55.532362240Z" level=debug msg="request: &ImageStatusRequest{Image:&ImageSpec{Image:quay.io/crio/oom,},Verbose:true,}" file="v1alpha2/api.pb.go:8226" id=84325e78-7d19-4b86-8428-be26874a4d9a
09:25:29 # time="2020-01-14 15:24:55.532556945Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]quay.io/crio/oom:latest\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.533277160Z" level=debug msg="response: &ImageStatusResponse{Image:&Image{Id:259cb9ee8ccba33f36ea25dab0224b602790b3e982788b55fd95bd47b5202684,RepoTags:[quay.io/crio/oom:latest],RepoDigests:[quay.io/crio/oom@sha256:3f540a296d709c376e5f0476ab624b7f300fa2cbe119a5464a2e0e391986eae5],Size_:5973904,Uid:nil,Username:,},Info:map[string]string{},}" file="v1alpha2/api.pb.go:8226" id=84325e78-7d19-4b86-8428-be26874a4d9a
09:25:29 # time="2020-01-14 15:24:55.544573905Z" level=debug msg="request: &ImageStatusRequest{Image:&ImageSpec{Image:quay.io/crio/oom,},Verbose:true,}" file="v1alpha2/api.pb.go:8226" id=5dee7fbd-4053-4427-878f-c1a411c065cf
09:25:29 # time="2020-01-14 15:24:55.544793710Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]quay.io/crio/oom:latest\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.545647628Z" level=debug msg="response: &ImageStatusResponse{Image:&Image{Id:259cb9ee8ccba33f36ea25dab0224b602790b3e982788b55fd95bd47b5202684,RepoTags:[quay.io/crio/oom:latest],RepoDigests:[quay.io/crio/oom@sha256:3f540a296d709c376e5f0476ab624b7f300fa2cbe119a5464a2e0e391986eae5],Size_:5973904,Uid:nil,Username:,},Info:map[string]string{},}" file="v1alpha2/api.pb.go:8226" id=5dee7fbd-4053-4427-878f-c1a411c065cf
09:25:29 # time="2020-01-14 15:24:55.553750704Z" level=debug msg="request: &ImageStatusRequest{Image:&ImageSpec{Image:quay.io/crio/stderr-test,},Verbose:true,}" file="v1alpha2/api.pb.go:8226" id=5883dcb5-6662-4856-a898-96823dec4e1f
09:25:29 # time="2020-01-14 15:24:55.553988409Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]quay.io/crio/stderr-test:latest\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.554763226Z" level=debug msg="response: &ImageStatusResponse{Image:&Image{Id:5501612c200f99317c33b7a02dfbe6e30a76deea821e0f115eb4a6ab7f2ef689,RepoTags:[quay.io/crio/stderr-test:latest],RepoDigests:[quay.io/crio/stderr-test@sha256:d551428befc4a6436e9db96e084e8d4da73bc4568d6db08072f14f40f639c868],Size_:5155772,Uid:nil,Username:,},Info:map[string]string{},}" file="v1alpha2/api.pb.go:8226" id=5883dcb5-6662-4856-a898-96823dec4e1f
09:25:29 # time="2020-01-14 15:24:55.567744507Z" level=debug msg="request: &ImageStatusRequest{Image:&ImageSpec{Image:quay.io/crio/stderr-test,},Verbose:true,}" file="v1alpha2/api.pb.go:8226" id=bea71607-3851-47e9-ad46-dbeb1ca6d1ce
09:25:29 # time="2020-01-14 15:24:55.567991812Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]quay.io/crio/stderr-test:latest\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.568858131Z" level=debug msg="response: &ImageStatusResponse{Image:&Image{Id:5501612c200f99317c33b7a02dfbe6e30a76deea821e0f115eb4a6ab7f2ef689,RepoTags:[quay.io/crio/stderr-test:latest],RepoDigests:[quay.io/crio/stderr-test@sha256:d551428befc4a6436e9db96e084e8d4da73bc4568d6db08072f14f40f639c868],Size_:5155772,Uid:nil,Username:,},Info:map[string]string{},}" file="v1alpha2/api.pb.go:8226" id=bea71607-3851-47e9-ad46-dbeb1ca6d1ce
09:25:29 # time="2020-01-14 15:24:55.577020408Z" level=debug msg="request: &ImageStatusRequest{Image:&ImageSpec{Image:quay.io/crio/busybox,},Verbose:true,}" file="v1alpha2/api.pb.go:8226" id=2d9a833f-aada-42cc-b6e4-d9097dbd67e2
09:25:29 # time="2020-01-14 15:24:55.577245413Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]quay.io/crio/busybox:latest\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.577833826Z" level=debug msg="response: &ImageStatusResponse{Image:&Image{Id:8ac48589692a53a9b8c2d1ceaa6b402665aa7fe667ba51ccc03002300856d8c7,RepoTags:[quay.io/crio/busybox:latest],RepoDigests:[quay.io/crio/busybox@sha256:85f389fc5830ba4269d3b4b9a4e8dfd32d5c5b8d9dda0586a9a0468d6961e5d5],Size_:1365270,Uid:nil,Username:,},Info:map[string]string{},}" file="v1alpha2/api.pb.go:8226" id=2d9a833f-aada-42cc-b6e4-d9097dbd67e2
09:25:29 # time="2020-01-14 15:24:55.588513957Z" level=debug msg="request: &ImageStatusRequest{Image:&ImageSpec{Image:quay.io/crio/busybox,},Verbose:true,}" file="v1alpha2/api.pb.go:8226" id=b6cf4fda-e3c4-42f6-b4b6-bb23b1ad3849
09:25:29 # time="2020-01-14 15:24:55.588981767Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]quay.io/crio/busybox:latest\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.589853686Z" level=debug msg="response: &ImageStatusResponse{Image:&Image{Id:8ac48589692a53a9b8c2d1ceaa6b402665aa7fe667ba51ccc03002300856d8c7,RepoTags:[quay.io/crio/busybox:latest],RepoDigests:[quay.io/crio/busybox@sha256:85f389fc5830ba4269d3b4b9a4e8dfd32d5c5b8d9dda0586a9a0468d6961e5d5],Size_:1365270,Uid:nil,Username:,},Info:map[string]string{},}" file="v1alpha2/api.pb.go:8226" id=b6cf4fda-e3c4-42f6-b4b6-bb23b1ad3849
09:25:29 # time="2020-01-14 15:24:55.599293291Z" level=debug msg="request: &ImageStatusRequest{Image:&ImageSpec{Image:quay.io/crio/image-volume-test,},Verbose:true,}" file="v1alpha2/api.pb.go:8226" id=ad00be94-f593-4bee-8f7f-e9520dd3c5c8
09:25:29 # time="2020-01-14 15:24:55.599529596Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]quay.io/crio/image-volume-test:latest\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.600171810Z" level=debug msg="response: &ImageStatusResponse{Image:&Image{Id:6aa3df42b4043d37070ae0fe51a1cbf71876c5d95d834d97940fac5e0b3006e1,RepoTags:[quay.io/crio/image-volume-test:latest],RepoDigests:[quay.io/crio/image-volume-test@sha256:98110701e9416f3db7a22cbe3476c76dcd3a2292001654b3014f781097035554],Size_:1299534,Uid:nil,Username:,},Info:map[string]string{},}" file="v1alpha2/api.pb.go:8226" id=ad00be94-f593-4bee-8f7f-e9520dd3c5c8
09:25:29 # time="2020-01-14 15:24:55.612243871Z" level=debug msg="request: &ImageStatusRequest{Image:&ImageSpec{Image:quay.io/crio/image-volume-test,},Verbose:true,}" file="v1alpha2/api.pb.go:8226" id=52e5226c-f585-4598-a347-95c5f05ce03e
09:25:29 # time="2020-01-14 15:24:55.612463776Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]quay.io/crio/image-volume-test:latest\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.613139991Z" level=debug msg="response: &ImageStatusResponse{Image:&Image{Id:6aa3df42b4043d37070ae0fe51a1cbf71876c5d95d834d97940fac5e0b3006e1,RepoTags:[quay.io/crio/image-volume-test:latest],RepoDigests:[quay.io/crio/image-volume-test@sha256:98110701e9416f3db7a22cbe3476c76dcd3a2292001654b3014f781097035554],Size_:1299534,Uid:nil,Username:,},Info:map[string]string{},}" file="v1alpha2/api.pb.go:8226" id=52e5226c-f585-4598-a347-95c5f05ce03e
09:25:29 # time="2020-01-14 15:24:55.624168930Z" level=debug msg="request: &RunPodSandboxRequest{Config:&PodSandboxConfig{Metadata:&PodSandboxMetadata{Name:podsandbox1,Uid:redhat-test-crio,Namespace:redhat.test.crio,Attempt:1,},Hostname:crictl_host,LogDirectory:,DnsConfig:&DNSConfig{Servers:[],Searches:[8.8.8.8],Options:[],},PortMappings:[]*PortMapping{},Labels:map[string]string{group: test,},Annotations:map[string]string{owner: hmeng,security.alpha.kubernetes.io/seccomp/pod: unconfined,},Linux:&LinuxPodSandboxConfig{CgroupParent:/Burstable/pod_123-456,SecurityContext:&LinuxSandboxSecurityContext{NamespaceOptions:&NamespaceOption{Network:POD,Pid:CONTAINER,Ipc:POD,},SelinuxOptions:&SELinuxOption{User:system_u,Role:system_r,Type:svirt_lxc_net_t,Level:s0:c4,c5,},RunAsUser:nil,ReadonlyRootfs:false,SupplementalGroups:[],Privileged:false,SeccompProfilePath:,RunAsGroup:nil,},Sysctls:map[string]string{},},},RuntimeHandler:,}" file="v1alpha2/api.pb.go:7618" id=e52ff9d4-d8e5-4b26-8183-f985b6e0f884
09:25:29 # time="2020-01-14 15:24:55.624249231Z" level=info msg="attempting to run pod sandbox with infra container: //POD" file="server/sandbox_run_linux.go:59" id=e52ff9d4-d8e5-4b26-8183-f985b6e0f884
09:25:29 # time="2020-01-14 15:24:55.624385934Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]k8s.gcr.io/pause:3.1\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.624525837Z" level=debug msg="reference \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]k8s.gcr.io/pause:3.1\" does not resolve to an image ID" file="storage/storage_reference.go:158"
09:25:29 # time="2020-01-14 15:24:55.624605239Z" level=debug msg="couldn't find image \"k8s.gcr.io/pause:3.1\", retrieving it" file="storage/runtime.go:191"
09:25:29 # time="2020-01-14 15:24:55.626864788Z" level=debug msg="parsed reference into \"[devicemapper@/tmp/tmp.t9m5gZy5ct/crio+/tmp/tmp.t9m5gZy5ct/crio-run:dm.directlvm_device_force=true,dm.thinp_percent=95,dm.thinp_metapercent=1,dm.thinp_autoextend_threshold=80,dm.thinp_autoextend_percent=20,dm.directlvm_device=/dev/sdb]k8s.gcr.io/pause:3.1\"" file="storage/storage_transport.go:174"
09:25:29 # time="2020-01-14 15:24:55.627061592Z" level=debug msg="reference rewritten from 'k8s.gcr.io/pause:3.1' to 'k8s.gcr.io/pause:3.1'" file="sysregistriesv2/system_registries_v2.go:52"
09:25:29 # time="2020-01-14 15:24:55.627151894Z" level=debug msg="Trying to pull \"k8s.gcr.io/pause:3.1\"" file="docker/docker_image_src.go:62"
09:25:29 # time="2020-01-14 15:24:55.627246196Z" level=debug msg="Credentials not found" file="config/config.go:117"
09:25:29 # time="2020-01-14 15:24:55.627305897Z" level=debug msg="Using registries.d directory /etc/containers/registries.d for sigstore configuration" file="docker/lookaside.go:51"
09:25:29 # time="2020-01-14 15:24:55.627353899Z" level=debug msg=" No signature storage configuration found for k8s.gcr.io/pause:3.1" file="docker/lookaside.go:174"
09:25:29 # time="2020-01-14 15:24:55.627406700Z" level=debug msg="Looking for TLS certificates and private keys in /etc/docker/certs.d/k8s.gcr.io" file="tlsclientconfig/tlsclientconfig.go:21"
09:25:29 # time="2020-01-14 15:24:55.627488901Z" level=debug msg="GET https://k8s.gcr.io/v2/" file="docker/docker_client.go:500"
09:25:29 # time="2020-01-14 15:24:55.751455587Z" level=debug msg="Ping https://k8s.gcr.io/v2/ status 401" file="docker/docker_client.go:628"
09:25:29 # time="2020-01-14 15:24:55.751630791Z" level=debug msg="GET https://k8s.gcr.io/v2/token?scope=repository%3Apause%3Apull&service=k8s.gcr.io" file="docker/docker_client.go:584"
09:25:29 # time="2020-01-14 15:24:55.827434034Z" level=debug msg="GET https://k8s.gcr.io/v2/pause/manifests/3.1" file="docker/docker_client.go:500"
09:25:29 # time="2020-01-14 15:24:55.985998469Z" level=debug msg="Using blob info cache at /var/lib/containers/cache/blob-info-cache-v1.boltdb" file="blobinfocache/default.go:73"
09:25:29 # time="2020-01-14 15:24:55.986339777Z" level=debug msg="Source is a manifest list; copying (only) instance sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610 for current system" file="copy/copy.go:276"
09:25:29 # time="2020-01-14 15:24:55.986426479Z" level=debug msg="GET https://k8s.gcr.io/v2/pause/manifests/sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610" file="docker/docker_client.go:500"
09:25:29 # time="2020-01-14 15:24:56.174967462Z" level=debug msg="IsRunningImageAllowed for image docker:k8s.gcr.io/pause:3.1" file="signature/policy_eval.go:270"
09:25:29 # time="2020-01-14 15:24:56.175055963Z" level=debug msg=" Using default policy section" file="signature/policy_eval.go:161"
09:25:29 # time="2020-01-14 15:24:56.175093264Z" level=debug msg=" Requirement 0: allowed" file="signature/policy_eval.go:284"
09:25:29 # time="2020-01-14 15:24:56.175128165Z" level=debug msg="Overall: allowed" file="signature/policy_eval.go:287"
09:25:29 # time="2020-01-14 15:24:56.175257768Z" level=debug msg="Downloading /v2/pause/blobs/sha256:da86e6ba6ca197bf6bc5e9d900febd906b133eaa4750e6bed647b0fbe50ed43e" file="docker/docker_image_src.go:237"
09:25:29 # time="2020-01-14 15:24:56.175320669Z" level=debug msg="GET https://k8s.gcr.io/v2/pause/blobs/sha256:da86e6ba6ca197bf6bc5e9d900febd906b133eaa4750e6bed647b0fbe50ed43e" file="docker/docker_client.go:500"
09:25:29 # time="2020-01-14 15:24:56.298596339Z" level=debug msg="Manifest has MIME type application/vnd.docker.distribution.manifest.v2+json, ordered candidate list [application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.v1+prettyjws, application/vnd.oci.image.manifest.v1+json, application/vnd.docker.distribution.manifest.v1+json]" file="copy/manifest.go:101"
09:25:29 # time="2020-01-14 15:24:56.298669340Z" level=debug msg="... will first try using the original manifest unmodified" file="copy/manifest.go:109"
09:25:29 # time="2020-01-14 15:24:56.299227752Z" level=debug msg="Downloading /v2/pause/blobs/sha256:67ddbfb20a22d7c0ea0df568069e7ffc42378467402d04f28ecfa244e78c5eb8" file="docker/docker_image_src.go:237"
09:25:29 # time="2020-01-14 15:24:56.299296754Z" level=debug msg="GET https://k8s.gcr.io/v2/pause/blobs/sha256:67ddbfb20a22d7c0ea0df568069e7ffc42378467402d04f28ecfa244e78c5eb8" file="docker/docker_client.go:500"
09:25:29 # time="2020-01-14 15:24:56.477429311Z" level=debug msg="Detected compression format gzip" file="compression/compression.go:110"
09:25:29 # time="2020-01-14 15:24:56.477532713Z" level=debug msg="Using original blob without modification" file="copy/copy.go:1150"
09:25:29 # time="2020-01-14 15:24:56.779410450Z" level=debug msg="No compression detected" file="compression/compression.go:117"
09:25:29 # time="2020-01-14 15:24:56.779500852Z" level=debug msg="Using original blob without modification" file="copy/copy.go:1150"
09:25:29 # time="2020-01-14 15:24:57.140029157Z" level=debug msg="devmapper: AddDevice START(hash=e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4 basehash=)" file="devmapper/deviceset.go:1906"
09:25:29 # time="2020-01-14 15:24:57.140145459Z" level=debug msg="devmapper: Failed to read /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4 with err: open /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4: no such file or directory" file="devmapper/deviceset.go:958"
09:25:29 # time="2020-01-14 15:24:57.182848684Z" level=debug msg="devmapper: registerDevice(16, e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:496"
09:25:29 # time="2020-01-14 15:24:57.197146293Z" level=debug msg="devmapper: AddDevice END(hash=e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4 basehash=)" file="devmapper/deviceset.go:1960"
09:25:29 # time="2020-01-14 15:24:57.296893151Z" level=debug msg="devmapper: activateDeviceIfNeeded(e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:518"
09:25:29 # time="2020-01-14 15:24:57.448115724Z" level=debug msg="Start untar layer" file="drivers/fsdiff.go:181"
09:25:29 # time="2020-01-14 15:24:57.553073395Z" level=debug msg="Untar time: 0.104956171s" file="drivers/fsdiff.go:186"
09:25:29 # time="2020-01-14 15:24:57.553151297Z" level=debug msg="devmapper: UnmountDevice START(hash=e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:2428"
09:25:29 # time="2020-01-14 15:24:57.553184098Z" level=debug msg="devmapper: Unmount(/tmp/tmp.t9m5gZy5ct/crio/devicemapper/mnt/e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:2442"
09:25:29 # time="2020-01-14 15:24:57.579951677Z" level=debug msg="devmapper: Unmount done" file="devmapper/deviceset.go:2446"
09:25:29 # time="2020-01-14 15:24:57.580036879Z" level=debug msg="devmapper: deactivateDevice START(e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:24:57.580149081Z" level=debug msg="devmapper: removeDevice START(container-8:1-274236-e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:2181"
09:25:29 # time="2020-01-14 15:24:57.639092257Z" level=debug msg="devmapper: removeDevice END(container-8:1-274236-e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:2200"
09:25:29 # time="2020-01-14 15:24:57.639162058Z" level=debug msg="devmapper: deactivateDevice END(e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:2172"
09:25:29 # time="2020-01-14 15:24:57.639224360Z" level=debug msg="devmapper: UnmountDevice END(hash=e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:2448"
09:25:29 # time="2020-01-14 15:24:57.835841314Z" level=debug msg="setting image creation date to 2017-12-20 21:30:49.042210931 +0000 UTC" file="storage/storage_image.go:753"
09:25:29 # time="2020-01-14 15:24:57.882074215Z" level=debug msg="created new image ID \"da86e6ba6ca197bf6bc5e9d900febd906b133eaa4750e6bed647b0fbe50ed43e\"" file="storage/storage_image.go:779"
09:25:29 # time="2020-01-14 15:24:57.923789218Z" level=debug msg="set names of image \"da86e6ba6ca197bf6bc5e9d900febd906b133eaa4750e6bed647b0fbe50ed43e\" to [k8s.gcr.io/pause:3.1]" file="storage/storage_image.go:820"
09:25:29 # time="2020-01-14 15:24:58.147725362Z" level=debug msg="saved image metadata \"{\\\"signatures-sizes\\\":{\\\"sha256:59eec8837a4d942cc19a52b8c09ea75121acc38114a2c68b98983ce9356b8610\\\":[]}}\"" file="storage/storage_image.go:897"
09:25:29 # time="2020-01-14 15:24:58.148170371Z" level=debug msg="successfully pulled image \"k8s.gcr.io/pause:3.1\"" file="storage/runtime.go:210"
09:25:29 # time="2020-01-14 15:24:58.148613581Z" level=debug msg="exporting opaque data as blob \"sha256:da86e6ba6ca197bf6bc5e9d900febd906b133eaa4750e6bed647b0fbe50ed43e\"" file="storage/storage_image.go:158"
09:25:29 # time="2020-01-14 15:24:58.148976989Z" level=debug msg="devmapper: AddDevice START(hash=efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e basehash=e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:1906"
09:25:29 # time="2020-01-14 15:24:58.149071091Z" level=debug msg="devmapper: Failed to read /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e with err: open /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e: no such file or directory" file="devmapper/deviceset.go:958"
09:25:29 # time="2020-01-14 15:24:58.166085059Z" level=debug msg="devmapper: registerDevice(17, efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:496"
09:25:29 # time="2020-01-14 15:24:58.180300366Z" level=debug msg="devmapper: AddDevice END(hash=efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e basehash=e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:1960"
09:25:29 # time="2020-01-14 15:24:58.302933118Z" level=debug msg="created pod sandbox \"22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d\"" file="storage/runtime.go:281"
09:25:29 # time="2020-01-14 15:24:58.343774202Z" level=debug msg="pod sandbox \"22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d\" has work directory \"/tmp/tmp.t9m5gZy5ct/crio/devicemapper-containers/22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d/userdata\"" file="storage/runtime.go:321"
09:25:29 # time="2020-01-14 15:24:58.343997406Z" level=debug msg="pod sandbox \"22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d\" has run directory \"/tmp/tmp.t9m5gZy5ct/crio-run/devicemapper-containers/22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d/userdata\"" file="storage/runtime.go:331"
09:25:29 # time="2020-01-14 15:24:58.409716428Z" level=warning msg="sysctl \"[]\" not of the format sysctl_name=value" file="server/sandbox_run_linux.go:429" id=e52ff9d4-d8e5-4b26-8183-f985b6e0f884
09:25:29 # time="2020-01-14 15:24:58.410581446Z" level=debug msg="devmapper: activateDeviceIfNeeded(efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:518"
09:25:29 # time="2020-01-14 15:24:58.567282435Z" level=debug msg="mounted container \"22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d\" at \"/tmp/tmp.t9m5gZy5ct/crio/devicemapper/mnt/efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e/rootfs\"" file="storage/runtime.go:426"
09:25:29 # time="2020-01-14 15:24:58.568613464Z" level=debug msg="running conmon: /usr/local/bin/conmon" args="[--syslog -c 22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d -n k8s_POD_podsandbox1_redhat.test.crio_redhat-test-crio_1 -u 22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d -r /usr/local/bin/kata-runtime -b /tmp/tmp.t9m5gZy5ct/crio-run/devicemapper-containers/22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d/userdata -p /tmp/tmp.t9m5gZy5ct/crio-run/devicemapper-containers/22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d/userdata/pidfile -l /var/log/crio/pods/22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d/22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d.log --exit-dir /tmp/tmp.t9m5gZy5ct/containers/exits --socket-dir-path /tmp/tmp.t9m5gZy5ct/containers --log-level debug --runtime-arg --root=/run/runc]" file="oci/runtime_oci.go:125"
09:25:29 # time="2020-01-14 15:24:58.571754432Z" level=warning msg="Failed to add conmon to cgroupfs sandbox cgroup: write /sys/fs/cgroup/unified/Burstable/pod_123-456/crio-conmon-22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d/tasks: open /sys/fs/cgroup/unified/Burstable/pod_123-456/crio-conmon-22917aad303227972e5a73749820ce3b7852fd44e221246d82c8b3b1e7bcc98d/tasks: permission denied" file="oci/oci_linux.go:57"
09:25:29 # time="2020-01-14 15:25:28.692707797Z" level=debug msg="Received container pid: -1" file="oci/runtime_oci.go:204"
09:25:29 # time="2020-01-14 15:25:28.692851100Z" level=error msg="Container creation error: Failed to check if grpc server is working: context deadline exceeded\n" file="oci/runtime_oci.go:207"
09:25:29 # time="2020-01-14 15:25:28.736051017Z" level=debug msg="devmapper: UnmountDevice START(hash=efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:2428"
09:25:29 # time="2020-01-14 15:25:28.736143319Z" level=debug msg="devmapper: Unmount(/tmp/tmp.t9m5gZy5ct/crio/devicemapper/mnt/efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:2442"
09:25:29 # time="2020-01-14 15:25:28.740574313Z" level=debug msg="devmapper: Unmount done" file="devmapper/deviceset.go:2446"
09:25:29 # time="2020-01-14 15:25:28.740638714Z" level=debug msg="devmapper: deactivateDevice START(efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:28.740747217Z" level=debug msg="devmapper: removeDevice START(container-8:1-274236-efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:2181"
09:25:29 # time="2020-01-14 15:25:28.774858641Z" level=debug msg="devmapper: removeDevice END(container-8:1-274236-efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:2200"
09:25:29 # time="2020-01-14 15:25:28.774931842Z" level=debug msg="devmapper: deactivateDevice END(efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:2172"
09:25:29 # time="2020-01-14 15:25:28.774992144Z" level=debug msg="devmapper: UnmountDevice END(hash=efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:2448"
09:25:29 # time="2020-01-14 15:25:28.820935319Z" level=debug msg="devmapper: DeleteDevice START(hash=efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e syncDelete=false)" file="devmapper/deviceset.go:2104"
09:25:29 # time="2020-01-14 15:25:28.820999920Z" level=debug msg="devmapper: issueDiscard START(device: efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)." file="devmapper/deviceset.go:2045"
09:25:29 # time="2020-01-14 15:25:28.821062222Z" level=debug msg="devmapper: activateDeviceIfNeeded(efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:518"
09:25:29 # time="2020-01-14 15:25:28.973230853Z" level=debug msg="devmapper: issueDiscard END(device: efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)." file="devmapper/deviceset.go:2069"
09:25:29 # time="2020-01-14 15:25:28.973369056Z" level=debug msg="devmapper: deactivateDevice START(efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:28.973546659Z" level=debug msg="devmapper: removeDevice START(container-8:1-274236-efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:2181"
09:25:29 # time="2020-01-14 15:25:29.011899574Z" level=debug msg="devmapper: removeDevice END(container-8:1-274236-efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:2200"
09:25:29 # time="2020-01-14 15:25:29.012039377Z" level=debug msg="devmapper: deactivateDevice END(efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:2172"
09:25:29 # time="2020-01-14 15:25:29.023759925Z" level=debug msg="devmapper: unregisterDevice(efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e)" file="devmapper/deviceset.go:479"
09:25:29 # time="2020-01-14 15:25:29.024151134Z" level=debug msg="devmapper: DeleteDevice END(hash=efec5ad40cbca46cfb4596e868fc4517796b5de553bf38fb8b1323e10a8f899e syncDelete=false)" file="devmapper/deviceset.go:2117"
09:25:29 # time="2020-01-14 15:25:29.129989679Z" level=debug msg="response error: container create failed: Failed to check if grpc server is working: context deadline exceeded\n" file="v1alpha2/api.pb.go:7618" id=e52ff9d4-d8e5-4b26-8183-f985b6e0f884
09:25:29 # time="2020-01-14T15:25:29Z" level=fatal msg="run pod sandbox failed: rpc error: code = Unknown desc = container create failed: Failed to check if grpc server is working: context deadline exceeded\n"
09:25:29 # time="2020-01-14 15:25:29.143298962Z" level=debug msg="request: &ListContainersRequest{Filter:&ContainerFilter{Id:,State:&ContainerStateValue{State:CONTAINER_RUNNING,},PodSandboxId:,LabelSelector:map[string]string{},},}" file="v1alpha2/api.pb.go:7780" id=c6325914-9f32-48b7-967b-8b049c6e6875
09:25:29 # time="2020-01-14 15:25:29.143407364Z" level=debug msg="no filters were applied, returning full container list" file="server/container_list.go:61" id=c6325914-9f32-48b7-967b-8b049c6e6875
09:25:29 # time="2020-01-14 15:25:29.143543767Z" level=debug msg="response: &ListContainersResponse{Containers:[]*Container{},}" file="v1alpha2/api.pb.go:7780" id=c6325914-9f32-48b7-967b-8b049c6e6875
09:25:29 # time="2020-01-14 15:25:29.156140534Z" level=debug msg="request: &ListPodSandboxRequest{Filter:&PodSandboxFilter{Id:,State:nil,LabelSelector:map[string]string{},},}" file="v1alpha2/api.pb.go:7690" id=c28218d7-b3f6-4db7-bb9d-374a75f9ee78
09:25:29 # time="2020-01-14 15:25:29.156258137Z" level=debug msg="response: &ListPodSandboxResponse{Items:[]*PodSandbox{},}" file="v1alpha2/api.pb.go:7690" id=c28218d7-b3f6-4db7-bb9d-374a75f9ee78
09:25:29 # time="2020-01-14 15:25:29.157786669Z" level=debug msg="received signal" file="crio/main.go:53" signal=terminated
09:25:29 # time="2020-01-14 15:25:29.157851871Z" level=debug msg="Caught SIGTERM" file="crio/main.go:63"
09:25:29 # time="2020-01-14 15:25:29.158067575Z" level=debug msg="devmapper: [deviceset container-8:1-274236] Shutdown()" file="devmapper/deviceset.go:2256"
09:25:29 # time="2020-01-14 15:25:29.158147677Z" level=debug msg="devmapper: Shutting down DeviceSet: /tmp/tmp.t9m5gZy5ct/crio/devicemapper" file="devmapper/deviceset.go:2257"
09:25:29 # time="2020-01-14 15:25:29.158087376Z" level=debug msg="hook monitoring canceled: context canceled" file="hooks/monitor.go:60"
09:25:29 # time="2020-01-14 15:25:29.158114276Z" level=debug msg="closed http server" file="crio/main.go:265"
09:25:29 # time="2020-01-14 15:25:29.158128376Z" level=debug msg="closing exit monitor..." file="server/server.go:729"
09:25:29 # time="2020-01-14 15:25:29.182019783Z" level=debug msg="devmapper: Failed to read /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/mnt with err: open /tmp/tmp.t9m5gZy5ct/crio/devicemapper/metadata/mnt: no such file or directory" file="devmapper/deviceset.go:958"
09:25:29 # time="2020-01-14 15:25:29.182140986Z" level=debug msg="devmapper: Shutdown lookup device mnt, error: devmapper: Unknown device mnt" file="devmapper/deviceset.go:2301"
09:25:29 # time="2020-01-14 15:25:29.182229388Z" level=debug msg="devmapper: deactivateDevice START(01d6f430ddfdf1203b505fbb03c6479802a3366609d5e0231a30f85f412f873d)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.182350790Z" level=debug msg="devmapper: deactivateDevice END(01d6f430ddfdf1203b505fbb03c6479802a3366609d5e0231a30f85f412f873d)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.182445192Z" level=debug msg="devmapper: deactivateDevice START(0314be9edf00a925d59f9b88c9d8ccb34447ab677078874d8c14e7a6816e21e1)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.182523794Z" level=debug msg="devmapper: deactivateDevice END(0314be9edf00a925d59f9b88c9d8ccb34447ab677078874d8c14e7a6816e21e1)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.182608696Z" level=debug msg="devmapper: deactivateDevice START(18a9c5dd4fc33b1b7f3e54d30fee0c94a9b0f280ba595a928508b8f79c925c66)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.182682597Z" level=debug msg="devmapper: deactivateDevice END(18a9c5dd4fc33b1b7f3e54d30fee0c94a9b0f280ba595a928508b8f79c925c66)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.182782900Z" level=debug msg="devmapper: deactivateDevice START(1a1edaafa91f809f5f7dd6367d47b4f36d7dced734a9628350e0fef133c68379)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.182855901Z" level=debug msg="devmapper: deactivateDevice END(1a1edaafa91f809f5f7dd6367d47b4f36d7dced734a9628350e0fef133c68379)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.182940703Z" level=debug msg="devmapper: deactivateDevice START(389ba2153eeb8a200660313dcd6f1f4a84ec8d80ec7c651100791b2c80dd121d)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.183010704Z" level=debug msg="devmapper: deactivateDevice END(389ba2153eeb8a200660313dcd6f1f4a84ec8d80ec7c651100791b2c80dd121d)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.183093406Z" level=debug msg="devmapper: deactivateDevice START(3fc666989c1d08d3ff91e75f335d898f525648e68e0264c50489ffe85b93eb76)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.183166908Z" level=debug msg="devmapper: deactivateDevice END(3fc666989c1d08d3ff91e75f335d898f525648e68e0264c50489ffe85b93eb76)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.183336911Z" level=debug msg="devmapper: deactivateDevice START(55e69498dbee26b17f32a9d6f122097319df6e9ec515ca44b4146848923a4a9f)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.183418313Z" level=debug msg="devmapper: deactivateDevice END(55e69498dbee26b17f32a9d6f122097319df6e9ec515ca44b4146848923a4a9f)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.183545416Z" level=debug msg="devmapper: deactivateDevice START(78ca90b1d5f1c01b1eab2929d02268e2cceb00512929f6d71b30bf8b41a22944)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.183625617Z" level=debug msg="devmapper: deactivateDevice END(78ca90b1d5f1c01b1eab2929d02268e2cceb00512929f6d71b30bf8b41a22944)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.183712119Z" level=debug msg="devmapper: deactivateDevice START(ad54249f0bda53d7537a95c55e114dfe1218194a9af78cff031597476adb96ba)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.183806921Z" level=debug msg="devmapper: deactivateDevice END(ad54249f0bda53d7537a95c55e114dfe1218194a9af78cff031597476adb96ba)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.183895023Z" level=debug msg="devmapper: deactivateDevice START(b0e4f203926e643573ffcdf7738dc79394cd4c208209cf359d697c29b4e14b94)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.183984425Z" level=debug msg="devmapper: deactivateDevice END(b0e4f203926e643573ffcdf7738dc79394cd4c208209cf359d697c29b4e14b94)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.186232073Z" level=debug msg="devmapper: deactivateDevice START(c00cd482af6ac6289450241b4a1c3dcfc4d91a0b1f9ac8c405ca5c8f3ff5319e)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.186364176Z" level=debug msg="devmapper: deactivateDevice END(c00cd482af6ac6289450241b4a1c3dcfc4d91a0b1f9ac8c405ca5c8f3ff5319e)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.186462478Z" level=debug msg="devmapper: deactivateDevice START(cd7100a72410606589a54b932cabd804a17f9ae5b42a1882bd56d263e02b6215)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.186556280Z" level=debug msg="devmapper: deactivateDevice END(cd7100a72410606589a54b932cabd804a17f9ae5b42a1882bd56d263e02b6215)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.186645182Z" level=debug msg="devmapper: deactivateDevice START(e154057080f406372ebecadc0bfb5ff8a7982a0d13823bab1be5b86926c6f860)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.186736283Z" level=debug msg="devmapper: deactivateDevice END(e154057080f406372ebecadc0bfb5ff8a7982a0d13823bab1be5b86926c6f860)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.186829485Z" level=debug msg="devmapper: deactivateDevice START(e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.186921787Z" level=debug msg="devmapper: deactivateDevice END(e17133b79956ad6f69ae7f775badd1c11bad2fc64f0529cab863b9d12fbaa5c4)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.187012389Z" level=debug msg="devmapper: deactivateDevice START(e88b3f82283bc59d5e0df427c824e9f95557e661fcb0ea15fb0fb6f97760f9d9)" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.187104291Z" level=debug msg="devmapper: deactivateDevice END(e88b3f82283bc59d5e0df427c824e9f95557e661fcb0ea15fb0fb6f97760f9d9)" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.187162392Z" level=debug msg="devmapper: deactivateDevice START()" file="devmapper/deviceset.go:2150"
09:25:29 # time="2020-01-14 15:25:29.187236094Z" level=debug msg="devmapper: deactivateDevice END()" file="devmapper/deviceset.go:2159"
09:25:29 # time="2020-01-14 15:25:29.187278895Z" level=debug msg="devmapper: [deviceset container-8:1-274236] Shutdown() END" file="devmapper/deviceset.go:2335"
09:25:29 # time="2020-01-14 15:25:29.211306305Z" level=debug msg="closed stream server" file="crio/main.go:295"
09:25:29 # time="2020-01-14 15:25:29.211440208Z" level=debug msg="closed monitors" file="crio/main.go:297"
09:25:29 # time="2020-01-14 15:25:29.211536710Z" level=debug msg="closed hook monitor" file="crio/main.go:300"
09:25:29 # time="2020-01-14 15:25:29.211598011Z" level=debug msg="closed main server" file="crio/main.go:305"
09:25:29 # 0
09:25:29 # File descriptor 3 (pipe:[3025794]) leaked on lvm invocation. Parent PID 91988: bash
09:25:29 #   Logical volume "thinpool" successfully removed
09:25:29 # File descriptor 3 (pipe:[3025794]) leaked on lvm invocation. Parent PID 91988: bash
09:25:29 #   Volume group "storage" successfully removed
09:25:29 # File descriptor 3 (pipe:[3025794]) leaked on lvm invocation. Parent PID 91988: bash
09:25:29 #   Labels on physical volume "/dev/sdb" successfully wiped.
09:26:01 ok 5 additional devices support
09:26:06 ok 6 additional devices permissions # skip This is not working (Issue https://github.com/kata-containers/tests/issues/714)
09:26:46 ok 7 ctr remove
09:27:17 ok 8 ctr lifecycle
09:27:49 ok 9 ctr logging
09:28:21 ok 10 ctr journald logging
09:28:52 ok 11 ctr logging [tty=true]
09:29:25 ok 12 ctr log max
09:29:56 ok 13 ctr log max with default value

See http://jenkins.katacontainers.io/job/kata-containers-tests-ubuntu-1804-PR-firecracker/1168/console
Here it is another failure in another CRI-O test
http://jenkins.katacontainers.io/job/kata-containers-tests-ubuntu-1804-PR-firecracker/1176/

However, I also have seen errors in docker tests (random), for example

16:10:31 • Failure [152.431 seconds]
16:10:31 docker kill
16:10:31 /tmp/jenkins/workspace/kata-containers-tests-ubuntu-1804-PR-firecracker/go/src/github.com/kata-containers/tests/integration/docker/kill_test.go:79
16:10:31   killing container
16:10:31   /tmp/jenkins/workspace/kata-containers-tests-ubuntu-1804-PR-firecracker/go/src/github.com/kata-containers/tests/vendor/github.com/onsi/ginkgo/extensions/table/table.go:92
16:10:31     with '28'(window changed) signal [It]
16:10:31     /tmp/jenkins/workspace/kata-containers-tests-ubuntu-1804-PR-firecracker/go/src/github.com/kata-containers/tests/vendor/github.com/onsi/ginkgo/extensions/table/table_entry.go:43
16:10:31 
16:10:31     Expected error:
16:10:31         <*errors.errorString | 0xc0001c17d0>: {
16:10:31             s: "Timeout reached after 120s",
16:10:31         }
16:10:31         Timeout reached after 120s
16:10:31     not to have occurred

See http://jenkins.katacontainers.io/job/kata-containers-tests-ubuntu-1804-PR-firecracker/1167/console

[GabyCT]

This is another random failure

10:54:55 Running command '/usr/bin/docker [docker ps -a -f name=v0EhH3oAXcvEMuWiMQdSVQk6OWk801 --format {{.Status}}]'
10:54:55 [docker ps -a -f name=v0EhH3oAXcvEMuWiMQdSVQk6OWk801 --format {{.Status}}]
10:54:55 Timeout: 120 seconds
10:54:55 Exit Code: 0
10:54:55 Stdout: Created
10:54:55 
10:54:55 Stderr: 
10:54:55 
10:54:55 • Failure [32.654 seconds]
10:54:55 Checking CPU cgroups in the host
10:54:55 /tmp/jenkins/workspace/kata-containers-tests-ubuntu-1804-PR-firecracker/go/src/github.com/kata-containers/tests/integration/docker/cgroups_test.go:147
10:54:55   checking whether cgroups are updated
10:54:55   /tmp/jenkins/workspace/kata-containers-tests-ubuntu-1804-PR-firecracker/go/src/github.com/kata-containers/tests/integration/docker/cgroups_test.go:209
10:54:55     updating container cpu and cpuset cgroup
10:54:55     /tmp/jenkins/workspace/kata-containers-tests-ubuntu-1804-PR-firecracker/go/src/github.com/kata-containers/tests/integration/docker/cgroups_test.go:210
10:54:55       should be updated [It]
10:54:55       /tmp/jenkins/workspace/kata-containers-tests-ubuntu-1804-PR-firecracker/go/src/github.com/kata-containers/tests/integration/docker/cgroups_test.go:211
10:54:55 
10:54:55       Expected
10:54:55           <int>: 125
10:54:55       to be zero-valued
10:54:55 
10:54:55       /tmp/jenkins/workspace/kata-containers-tests-ubuntu-1804-PR-firecracker/go/src/github.com/kata-containers/tests/integration/docker/cgroups_test.go:216