Failing test on Kata runtime (container_min_memory) #8074
Labels
kind/failing-test
Categorizes issue or PR as related to a consistently or frequently failing test.
Comments
roman-kiselenko
added
the
kind/failing-test
This comment was marked as outdated.
This comment was marked as outdated.
|
testout.txtnot ok 216 run container with container_min_memory 17.5MiB
# (in test file image.bats, line 466)
# `run ! crictl run "$TESTDIR"/memory.json "$TESTDATA"/sandbox_config.json' failed, expected nonzero exit code!
# time="2024-04-22T16:51:23Z" level=warning msg="Support for the 'registries' option has been dropped but it is referenced in \"/etc/crio/crio.conf.d/01-registries.conf\". Please use containers-registries.conf(5) for configuring unqualified-search registries instead."
# time="2024-04-22 16:51:23.029536596Z" level=info msg="Starting CRI-O, version: 1.30.0, git: 167623d51b6ed92c021c36a57d6ac5d3b323b9c3(dirty)"
# level=info msg="Using default capabilities: CAP_CHOWN, CAP_DAC_OVERRIDE, CAP_FSETID, CAP_FOWNER, CAP_SETGID, CAP_SETUID, CAP_SETPCAP, CAP_NET_BIND_SERVICE, CAP_KILL"
# time="2024-04-22 16:51:23.067373281Z" level=info msg="Starting CRI-O, version: 1.30.0, git: 167623d51b6ed92c021c36a57d6ac5d3b323b9c3(dirty)"
# level=info msg="Using default capabilities: CAP_CHOWN, CAP_DAC_OVERRIDE, CAP_FSETID, CAP_FOWNER, CAP_SETGID, CAP_SETUID, CAP_SETPCAP, CAP_NET_BIND_SERVICE, CAP_KILL"
# time="2024-04-22T16:51:23Z" level=fatal msg="validate service connection: validate CRI v1 runtime API for endpoint \"unix:///tmp/tmp.C2aMvNzruC/crio.sock\": rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing: dial unix /tmp/tmp.C2aMvNzruC/crio.sock: connect: no such file or directory\""
# Image is up to date for quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32
# f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f
# # --- crio.log :: ---
# time="2024-04-22 16:51:23.119746698Z" level=info msg="Starting CRI-O, version: 1.30.0, git: 167623d51b6ed92c021c36a57d6ac5d3b323b9c3(dirty)"
# time="2024-04-22 16:51:23.124988355Z" level=info msg="Node configuration value for hugetlb cgroup is true"
# time="2024-04-22 16:51:23.124999744Z" level=info msg="Node configuration value for pid cgroup is true"
# time="2024-04-22 16:51:23.125045714Z" level=info msg="Node configuration value for memoryswap cgroup is true"
# time="2024-04-22 16:51:23.125051134Z" level=info msg="Node configuration value for cgroup v2 is true"
# time="2024-04-22 16:51:23.133691495Z" level=info msg="Node configuration value for systemd AllowedCPUs is true"
# time="2024-04-22 16:51:23.133782273Z" level=debug msg="[graphdriver] trying provided driver \"overlay\"" file="drivers/driver.go:362"
# time="2024-04-22 16:51:23.133913156Z" level=debug msg="Cached value indicated that overlay is supported" file="overlay/overlay.go:247"
# time="2024-04-22 16:51:23.133947539Z" level=debug msg="Cached value indicated that overlay is supported" file="overlay/overlay.go:247"
# time="2024-04-22 16:51:23.134692560Z" level=debug msg="overlay: test mount indicated that metacopy is being used" file="overlay/overlay.go:415"
# time="2024-04-22 16:51:23.135549937Z" level=info msg="Not using native diff for overlay, this may cause degraded performance for building images: kernel has CONFIG_OVERLAY_FS_REDIRECT_DIR enabled" file="overlay/overlay.go:808"
# time="2024-04-22 16:51:23.135612807Z" level=debug msg="backingFs=tmpfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=true" file="overlay/overlay.go:467"
# time="2024-04-22 16:51:23.135955823Z" level=info msg="Using default capabilities: CAP_CHOWN, CAP_DAC_OVERRIDE, CAP_FSETID, CAP_FOWNER, CAP_SETGID, CAP_SETUID, CAP_SETPCAP, CAP_NET_BIND_SERVICE, CAP_KILL" file="capabilities/capabilities_linux.go:38"
# time="2024-04-22 16:51:23.136089611Z" level=debug msg="Using runtime executable from $PATH \"/usr/local/sbin/runc\"" file="config/config.go:1583"
# time="2024-04-22 16:51:23.136122572Z" level=debug msg="Found valid runtime \"runc\" for runtime_path \"/usr/local/sbin/runc\"" file="config/config.go:1594"
# time="2024-04-22 16:51:23.136167596Z" level=debug msg="Allowed annotations for runtime: [io.containers.trace-syscall io.kubernetes.cri-o.Devices]" file="config/config.go:1628"
# time="2024-04-22 16:51:23.136213768Z" level=debug msg="Found valid runtime \"containerd-shim-kata-v2\" for runtime_path \"/opt/kata/bin/containerd-shim-kata-v2\"" file="config/config.go:1594"
# time="2024-04-22 16:51:23.136241431Z" level=debug msg="Allowed annotations for runtime: []" file="config/config.go:1628"
# time="2024-04-22 16:51:23.136258984Z" level=debug msg="Found valid runtime \"mem\" for runtime_path \"/opt/kata/bin/containerd-shim-kata-v2\"" file="config/config.go:1594"
# time="2024-04-22 16:51:23.136287940Z" level=debug msg="Allowed annotations for runtime: []" file="config/config.go:1628"
# time="2024-04-22 16:51:23.141296565Z" level=info msg="Using runtime handler runc version 1.2.0-rc.1+dev, commit: v1.2.0-rc.1-14-g6a2813f1, spec: 1.2.0, go: go1.21.9, libseccomp: 2.5.3" file="config/config.go:1291"
# time="2024-04-22 16:51:23.141965950Z" level=debug msg="Runtime handler \"runc\" container minimum memory set to 12582912 bytes" file="config/config.go:1300"
# time="2024-04-22 16:51:23.146651767Z" level=debug msg="Runtime handler \"runc\" supports User and Group ID-mappings" file="config/config.go:1317"
# time="2024-04-22 16:51:23.146688900Z" level=debug msg="Runtime handler \"runc\" supports Recursive Read-only (RRO) mounts" file="config/config.go:1326"
# time="2024-04-22 16:51:23.161838981Z" level=info msg="Using runtime handler Kata Containers containerd shim (Golang): id: \"io.containerd.kata.v2\", version: 3.1.3, commit: ee57732fe08504773b1b5474f2248834ae1fbd66" file="config/config.go:1291"
# time="2024-04-22 16:51:23.161885317Z" level=debug msg="Runtime handler \"containerd-shim-kata-v2\" container minimum memory set to 12582912 bytes" file="config/config.go:1300"
# time="2024-04-22 16:51:23.176544169Z" level=error msg="Getting /opt/kata/bin/containerd-shim-kata-v2 OCI runtime features failed: io.containerd.kata.v2: shim namespace cannot be empty: exit status 1" file="config/config.go:1306"
# time="2024-04-22 16:51:23.192534046Z" level=info msg="Using runtime handler Kata Containers containerd shim (Golang): id: \"io.containerd.kata.v2\", version: 3.1.3, commit: ee57732fe08504773b1b5474f2248834ae1fbd66" file="config/config.go:1291"
# time="2024-04-22 16:51:23.192575881Z" level=debug msg="Runtime handler \"mem\" container minimum memory set to 18350080 bytes" file="config/config.go:1300"
# time="2024-04-22 16:51:23.206806559Z" level=error msg="Getting /opt/kata/bin/containerd-shim-kata-v2 OCI runtime features failed: io.containerd.kata.v2: shim namespace cannot be empty: exit status 1" file="config/config.go:1306"
# time="2024-04-22 16:51:23.206935577Z" level=debug msg="Loading registries configuration \"/etc/containers/registries.conf\"" file="sysregistriesv2/system_registries_v2.go:926"
# time="2024-04-22 16:51:23.207232453Z" level=debug msg="Loading registries configuration \"/etc/containers/registries.conf.d/000-shortnames.conf\"" file="sysregistriesv2/system_registries_v2.go:926"
# time="2024-04-22 16:51:23.208809768Z" level=debug msg="Using hooks directory: /tmp/tmp.C2aMvNzruC/hooks" file="config/config.go:1153"
# time="2024-04-22 16:51:23.208915737Z" level=info msg="Using pinns executable: /usr/go/src/github.com/cri-o/cri-o/bin/pinns" file="config/config.go:1468"
# time="2024-04-22 16:51:23.208971667Z" level=debug msg="Using criu from $PATH: /usr/sbin/criu" file="config/config.go:1462"
# time="2024-04-22 16:51:23.208990097Z" level=info msg="Checkpoint/restore support enabled" file="config/config.go:1178"
# time="2024-04-22 16:51:23.209019000Z" level=info msg="Using the internal default seccomp profile" file="seccomp/seccomp.go:139"
# time="2024-04-22 16:51:23.209040800Z" level=info msg="AppArmor is disabled by the system or at CRI-O build-time" file="apparmor/apparmor_linux.go:35"
# time="2024-04-22 16:51:23.209062252Z" level=info msg="No blockio config file specified, blockio not configured" file="blockio/blockio.go:74"
# time="2024-04-22 16:51:23.209082745Z" level=info msg="RDT not available in the host system" file="rdt/rdt.go:56"
# time="2024-04-22 16:51:23.209100526Z" level=debug msg="Monitor path /usr/bin/conmon is becoming /usr/bin/conmon" file="config/config.go:1358"
# time="2024-04-22 16:51:23.209123232Z" level=info msg="Using conmon executable: /usr/bin/conmon" file="config/config.go:1468"
# time="2024-04-22 16:51:23.211370615Z" level=info msg="Conmon does support the --sync option" file="conmonmgr/conmonmgr.go:85"
# time="2024-04-22 16:51:23.211432641Z" level=info msg="Conmon does support the --log-global-size-max option" file="conmonmgr/conmonmgr.go:71"
# time="2024-04-22 16:51:23.211464108Z" level=debug msg="Monitor path is becoming /usr/bin/conmon" file="config/config.go:1358"
# time="2024-04-22 16:51:23.211491165Z" level=info msg="Using conmon executable: /usr/bin/conmon" file="config/config.go:1468"
# time="2024-04-22 16:51:23.213537738Z" level=info msg="Conmon does support the --sync option" file="conmonmgr/conmonmgr.go:85"
# time="2024-04-22 16:51:23.213564688Z" level=info msg="Conmon does support the --log-global-size-max option" file="conmonmgr/conmonmgr.go:71"
# time="2024-04-22 16:51:23.216752552Z" level=info msg="Found CNI network crio (type=bridge) at /tmp/tmp.C2aMvNzruC/cni/net.d/10-crio.conf" file="ocicni/ocicni.go:343"
# time="2024-04-22 16:51:23.216803868Z" level=info msg="Updated default CNI network name to crio" file="ocicni/ocicni.go:375"
# time="2024-04-22 16:51:23.217199491Z" level=debug msg="reading hooks from /tmp/tmp.C2aMvNzruC/hooks" file="hooks/read.go:65"
# time="2024-04-22 16:51:23.220811145Z" level=debug msg="Golang's threads limit set to 230670" file="server/server_linux.go:139"
# time="2024-04-22 16:51:23.221073321Z" level=debug msg="Sandboxes: []" file="server/server.go:531"
# time="2024-04-22 16:51:23.221140843Z" level=info msg="Registered SIGHUP reload watcher" file="server/server.go:583"
# time="2024-04-22 16:51:23.221187418Z" level=debug msg="Metrics are disabled" file="server/server.go:541"
# time="2024-04-22 16:51:23.221235280Z" level=info msg="Starting seccomp notifier watcher" file="server/server_linux.go:22"
# time="2024-04-22 16:51:23.221323961Z" level=info msg="Create NRI interface" file="nri/nri.go:94"
# time="2024-04-22 16:51:23.221450158Z" level=info msg="runtime interface created" file="adaptation/adaptation.go:146"
# time="2024-04-22 16:51:23.221492619Z" level=info msg="Registered domain \"k8s.io\" with NRI" file="nri/domain.go:43"
# time="2024-04-22 16:51:23.221513989Z" level=info msg="runtime interface starting up..." file="adaptation/adaptation.go:153"
# time="2024-04-22 16:51:23.221532675Z" level=info msg="starting plugins..." file="adaptation/adaptation.go:323"
# time="2024-04-22 16:51:23.224131256Z" level=debug msg="monitoring \"/tmp/tmp.C2aMvNzruC/hooks\" for hooks" file="hooks/monitor.go:43"
# time="2024-04-22 16:51:24.138658454Z" level=debug msg="Request: &VersionRequest{Version:,}" file="otel-collector/interceptors.go:62" id=0adc1ed1-45e6-455e-89ea-843c74ccac5b name=/runtime.v1.RuntimeService/Version
# time="2024-04-22 16:51:24.138826194Z" level=debug msg="Response: &VersionResponse{Version:0.1.0,RuntimeName:cri-o,RuntimeVersion:1.30.0,RuntimeApiVersion:v1,}" file="otel-collector/interceptors.go:74" id=0adc1ed1-45e6-455e-89ea-843c74ccac5b name=/runtime.v1.RuntimeService/Version
# time="2024-04-22 16:51:24.139446658Z" level=debug msg="Request: &StatusRequest{Verbose:true,}" file="otel-collector/interceptors.go:62" id=f095ed94-36a5-4986-895f-8e894c3da29d name=/runtime.v1.RuntimeService/Status
# time="2024-04-22 16:51:24.139624200Z" 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{config: {\"sandboxImage\":\"registry.k8s.io/pause:3.9\"},},RuntimeHandlers:[]*RuntimeHandler{&RuntimeHandler{Name:runc,Features:&RuntimeHandlerFeatures{RecursiveReadOnlyMounts:true,UserNamespaces:true,},},&RuntimeHandler{Name:containerd-shim-kata-v2,Features:&RuntimeHandlerFeatures{RecursiveReadOnlyMounts:false,UserNamespaces:false,},},&RuntimeHandler{Name:,Features:&RuntimeHandlerFeatures{RecursiveReadOnlyMounts:false,UserNamespaces:false,},},&RuntimeHandler{Name:mem,Features:&RuntimeHandlerFeatures{RecursiveReadOnlyMounts:false,UserNamespaces:false,},},},}" file="otel-collector/interceptors.go:74" id=f095ed94-36a5-4986-895f-8e894c3da29d name=/runtime.v1.RuntimeService/Status
# time="2024-04-22 16:51:24.162570554Z" level=debug msg="Request: &ImageFsInfoRequest{}" file="otel-collector/interceptors.go:62" id=2b438e88-03b3-4318-a774-bbf58ae77f70 name=/runtime.v1.ImageService/ImageFsInfo
# time="2024-04-22 16:51:24.162851567Z" level=debug msg="Response: &ImageFsInfoResponse{ImageFilesystems:[]*FilesystemUsage{&FilesystemUsage{Timestamp:1713804684162730412,FsId:&FilesystemIdentifier{Mountpoint:/tmp/tmp.C2aMvNzruC/crio/overlay-images,},UsedBytes:&UInt64Value{Value:18793,},InodesUsed:&UInt64Value{Value:15,},},},ContainerFilesystems:[]*FilesystemUsage{&FilesystemUsage{Timestamp:1713804684162730412,FsId:&FilesystemIdentifier{Mountpoint:/tmp/tmp.C2aMvNzruC/crio/overlay-images,},UsedBytes:&UInt64Value{Value:18793,},InodesUsed:&UInt64Value{Value:15,},},},}" file="otel-collector/interceptors.go:74" id=2b438e88-03b3-4318-a774-bbf58ae77f70 name=/runtime.v1.ImageService/ImageFsInfo
# time="2024-04-22 16:51:24.163530823Z" level=debug msg="Request: &ListImagesRequest{Filter:&ImageFilter{Image:&ImageSpec{Image:,Annotations:map[string]string{},UserSpecifiedImage:,RuntimeHandler:,},},}" file="otel-collector/interceptors.go:62" id=009a0db5-21c3-4071-be35-948dfd0701c2 name=/runtime.v1.ImageService/ListImages
# time="2024-04-22 16:51:24.163918186Z" level=debug msg="exporting opaque data as blob \"sha256:e6f1816883972d4be47bd48879a08919b96afcd344132622e4d444987919323c\"" file="storage/storage_src.go:115"
# time="2024-04-22 16:51:24.164897605Z" level=debug msg="exporting opaque data as blob \"sha256:492b81c586bf4fe31298733e7dd38ad35d03f5288a6810835d5d8c3c064d6837\"" file="storage/storage_src.go:115"
# time="2024-04-22 16:51:24.165496910Z" level=debug msg="exporting opaque data as blob \"sha256:49046f34f90ef0d548d29de0645ec534343ebde196badba8e29f2f2731d5b1c8\"" file="storage/storage_src.go:115"
# time="2024-04-22 16:51:24.165926030Z" level=debug msg="Response: &ListImagesResponse{Images:[]*Image{&Image{Id:e6f1816883972d4be47bd48879a08919b96afcd344132622e4d444987919323c,RepoTags:[registry.k8s.io/pause:3.9],RepoDigests:[registry.k8s.io/pause@sha256:8d4106c88ec0bd28001e34c975d65175d994072d65341f62a8ab0754b0fafe10],Size_:748009,Uid:&Int64Value{Value:65535,},Username:,Spec:nil,Pinned:true,},&Image{Id:492b81c586bf4fe31298733e7dd38ad35d03f5288a6810835d5d8c3c064d6837,RepoTags:[quay.io/crio/fedora-crio-ci:latest],RepoDigests:[quay.io/crio/fedora-crio-ci@sha256:7f3bd3e9c21eb31e22ea0d8bcf5f67e3dcc07bd7834028ea003a40aa796493f3],Size_:409410320,Uid:nil,Username:,Spec:nil,Pinned:false,},&Image{Id:49046f34f90ef0d548d29de0645ec534343ebde196badba8e29f2f2731d5b1c8,RepoTags:[quay.io/crio/hello-wasm:latest],RepoDigests:[quay.io/crio/hello-wasm@sha256:b596de4304d92958b92e55e042099a5092210851d91b6c74d8d78da5151b132d],Size_:2157724,Uid:nil,Username:,Spec:nil,Pinned:false,},},}" file="otel-collector/interceptors.go:74" id=009a0db5-21c3-4071-be35-948dfd0701c2 name=/runtime.v1.ImageService/ListImages
# time="2024-04-22 16:51:24.243839264Z" level=debug msg="Request: &ImageFsInfoRequest{}" file="otel-collector/interceptors.go:62" id=30b72566-7b4a-4f35-bbd0-0ef2a1bc4375 name=/runtime.v1.ImageService/ImageFsInfo
# time="2024-04-22 16:51:24.244061696Z" level=debug msg="Response: &ImageFsInfoResponse{ImageFilesystems:[]*FilesystemUsage{&FilesystemUsage{Timestamp:1713804684244023509,FsId:&FilesystemIdentifier{Mountpoint:/tmp/tmp.C2aMvNzruC/crio/overlay-images,},UsedBytes:&UInt64Value{Value:18793,},InodesUsed:&UInt64Value{Value:15,},},},ContainerFilesystems:[]*FilesystemUsage{&FilesystemUsage{Timestamp:1713804684244023509,FsId:&FilesystemIdentifier{Mountpoint:/tmp/tmp.C2aMvNzruC/crio/overlay-images,},UsedBytes:&UInt64Value{Value:18793,},InodesUsed:&UInt64Value{Value:15,},},},}" file="otel-collector/interceptors.go:74" id=30b72566-7b4a-4f35-bbd0-0ef2a1bc4375 name=/runtime.v1.ImageService/ImageFsInfo
# time="2024-04-22 16:51:24.244701034Z" level=debug msg="Request: &PullImageRequest{Image:&ImageSpec{Image:quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32,Annotations:map[string]string{},UserSpecifiedImage:,RuntimeHandler:,},Auth:nil,SandboxConfig:nil,}" file="otel-collector/interceptors.go:62" id=bd27fc67-f956-4a21-a627-dbffd5938a03 name=/runtime.v1.ImageService/PullImage
# time="2024-04-22 16:51:24.244769381Z" level=info msg="Pulling image: quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32" file="server/image_pull.go:40" id=bd27fc67-f956-4a21-a627-dbffd5938a03 name=/runtime.v1.ImageService/PullImage
# time="2024-04-22 16:51:24.244805201Z" level=debug msg="Using pull policy path for image quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32: /usr/go/src/github.com/cri-o/cri-o/test/policy.json" file="server/image_pull.go:149" id=bd27fc67-f956-4a21-a627-dbffd5938a03 name=/runtime.v1.ImageService/PullImage
# time="2024-04-22 16:51:24.244831379Z" level=debug msg="Skipping non-existing decryption_keys_path: /etc/crio/keys/" file="server/utils.go:89"
# time="2024-04-22 16:51:24.246399329Z" level=debug msg="Using registries.d directory /etc/containers/registries.d" file="docker/registries_d.go:80"
# time="2024-04-22 16:51:24.246692508Z" level=info msg="Trying to access \"quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32\"" file="docker/docker_image_src.go:92"
# time="2024-04-22 16:51:24.246746684Z" level=debug msg="No credentials matching quay.io/crio/alpine found in /run/containers/0/auth.json" file="config/config.go:846"
# time="2024-04-22 16:51:24.246787312Z" level=debug msg="No credentials matching quay.io/crio/alpine found in /root/.config/containers/auth.json" file="config/config.go:846"
# time="2024-04-22 16:51:24.246812204Z" level=debug msg="No credentials matching quay.io/crio/alpine found in /root/.docker/config.json" file="config/config.go:846"
# time="2024-04-22 16:51:24.246833063Z" level=debug msg="No credentials matching quay.io/crio/alpine found in /root/.dockercfg" file="config/config.go:846"
# time="2024-04-22 16:51:24.246850559Z" level=debug msg="No credentials for quay.io/crio/alpine found" file="config/config.go:272"
# time="2024-04-22 16:51:24.246872587Z" level=debug msg=" Lookaside configuration: using \"default-docker\" configuration" file="docker/registries_d.go:221"
# time="2024-04-22 16:51:24.246900777Z" level=debug msg=" No signature storage configuration found for quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32, using built-in default file:///var/lib/containers/sigstore" file="docker/registries_d.go:176"
# time="2024-04-22 16:51:24.246929442Z" level=debug msg="Looking for TLS certificates and private keys in /etc/docker/certs.d/quay.io" file="tlsclientconfig/tlsclientconfig.go:20"
# time="2024-04-22 16:51:24.246952848Z" level=debug msg=" Sigstore attachments: using \"default-docker\" configuration" file="docker/registries_d.go:254"
# time="2024-04-22 16:51:24.246995079Z" level=debug msg="GET https://quay.io/v2/" file="docker/docker_client.go:639"
# time="2024-04-22 16:51:24.387392673Z" level=debug msg="Ping https://quay.io/v2/ status 401" file="docker/docker_client.go:909"
# time="2024-04-22 16:51:24.387588327Z" level=debug msg="GET https://quay.io/v2/auth?scope=repository%3Acrio%2Falpine%3Apull&service=quay.io" file="docker/docker_client.go:869"
# time="2024-04-22 16:51:24.581272950Z" level=debug msg="Increasing token expiration to: 60 seconds" file="docker/docker_client.go:158"
# time="2024-04-22 16:51:24.581355071Z" level=debug msg="GET https://quay.io/v2/crio/alpine/manifests/sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32" file="docker/docker_client.go:639"
# time="2024-04-22 16:51:24.635998738Z" level=debug msg="Content-Type from manifest GET is \"application/vnd.docker.distribution.manifest.v2+json\"" file="docker/docker_client.go:972"
# time="2024-04-22 16:51:24.636243980Z" level=debug msg="reference \"[overlay@/tmp/tmp.C2aMvNzruC/crio+/tmp/tmp.C2aMvNzruC/crio-run:overlay.mountopt=nodev,metacopy=on,overlay.mountopt=metacopy=on]quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32\" does not resolve to an image ID" file="storage/storage_reference.go:149"
# time="2024-04-22 16:51:24.637764082Z" level=debug msg="Using registries.d directory /etc/containers/registries.d" file="docker/registries_d.go:80"
# time="2024-04-22 16:51:24.637967545Z" level=info msg="Trying to access \"quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32\"" file="docker/docker_image_src.go:92"
# time="2024-04-22 16:51:24.638013612Z" level=debug msg="No credentials matching quay.io/crio/alpine found in /run/containers/0/auth.json" file="config/config.go:846"
# time="2024-04-22 16:51:24.638041142Z" level=debug msg="No credentials matching quay.io/crio/alpine found in /root/.config/containers/auth.json" file="config/config.go:846"
# time="2024-04-22 16:51:24.638072042Z" level=debug msg="No credentials matching quay.io/crio/alpine found in /root/.docker/config.json" file="config/config.go:846"
# time="2024-04-22 16:51:24.638092992Z" level=debug msg="No credentials matching quay.io/crio/alpine found in /root/.dockercfg" file="config/config.go:846"
# time="2024-04-22 16:51:24.638111087Z" level=debug msg="No credentials for quay.io/crio/alpine found" file="config/config.go:272"
# time="2024-04-22 16:51:24.638134823Z" level=debug msg=" Lookaside configuration: using \"default-docker\" configuration" file="docker/registries_d.go:221"
# time="2024-04-22 16:51:24.638157138Z" level=debug msg=" No signature storage configuration found for quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32, using built-in default file:///var/lib/containers/sigstore" file="docker/registries_d.go:176"
# time="2024-04-22 16:51:24.638192987Z" level=debug msg="Looking for TLS certificates and private keys in /etc/docker/certs.d/quay.io" file="tlsclientconfig/tlsclientconfig.go:20"
# time="2024-04-22 16:51:24.638218554Z" level=debug msg=" Sigstore attachments: using \"default-docker\" configuration" file="docker/registries_d.go:254"
# time="2024-04-22 16:51:24.638247106Z" level=debug msg="GET https://quay.io/v2/" file="docker/docker_client.go:639"
# time="2024-04-22 16:51:24.759008493Z" level=debug msg="Ping https://quay.io/v2/ status 401" file="docker/docker_client.go:909"
# time="2024-04-22 16:51:24.759131574Z" level=debug msg="GET https://quay.io/v2/auth?scope=repository%3Acrio%2Falpine%3Apull&service=quay.io" file="docker/docker_client.go:869"
# time="2024-04-22 16:51:24.945577454Z" level=debug msg="Increasing token expiration to: 60 seconds" file="docker/docker_client.go:158"
# time="2024-04-22 16:51:24.945635729Z" level=debug msg="GET https://quay.io/v2/crio/alpine/manifests/sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32" file="docker/docker_client.go:639"
# time="2024-04-22 16:51:25.027803412Z" level=debug msg="Content-Type from manifest GET is \"application/vnd.docker.distribution.manifest.v2+json\"" file="docker/docker_client.go:972"
# time="2024-04-22 16:51:25.028647405Z" level=debug msg="Using SQLite blob info cache at /var/lib/containers/cache/blob-info-cache-v1.sqlite" file="blobinfocache/default.go:74"
# time="2024-04-22 16:51:25.028755657Z" level=debug msg="IsRunningImageAllowed for image docker:quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32" file="signature/policy_eval.go:274"
# time="2024-04-22 16:51:25.028793540Z" level=debug msg=" Using default policy section" file="signature/policy_eval.go:162"
# time="2024-04-22 16:51:25.028813417Z" level=debug msg=" Requirement 0: allowed" file="signature/policy_eval.go:288"
# time="2024-04-22 16:51:25.028831901Z" level=debug msg="Overall: allowed" file="signature/policy_eval.go:291"
# time="2024-04-22 16:51:25.028896462Z" level=debug msg="Downloading /v2/crio/alpine/blobs/sha256:78a2ce922f8665f5a227dc5cd9fda87221acba8a7a952b9665f99bc771a29963" file="docker/docker_client.go:1046"
# time="2024-04-22 16:51:25.028931933Z" level=debug msg="GET https://quay.io/v2/crio/alpine/blobs/sha256:78a2ce922f8665f5a227dc5cd9fda87221acba8a7a952b9665f99bc771a29963" file="docker/docker_client.go:639"
# time="2024-04-22 16:51:25.156558473Z" level=debug msg="Reading /var/lib/containers/sigstore/crio/alpine@sha256=65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32/signature-1" file="docker/docker_image_src.go:484"
# time="2024-04-22 16:51:25.156936621Z" level=debug msg="Looking for sigstore attachments in quay.io/crio/alpine:sha256-65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32.sig" file="docker/docker_client.go:1113"
# time="2024-04-22 16:51:25.156982629Z" level=debug msg="GET https://quay.io/v2/crio/alpine/manifests/sha256-65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32.sig" file="docker/docker_client.go:639"
# time="2024-04-22 16:51:25.217464527Z" level=debug msg="Content-Type from manifest GET is \"application/json\"" file="docker/docker_client.go:972"
# time="2024-04-22 16:51:25.217650691Z" level=debug msg="Fetching sigstore attachment manifest failed, assuming it does not exist: reading manifest sha256-65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32.sig in quay.io/crio/alpine: manifest unknown" file="docker/docker_client.go:1120"
# time="2024-04-22 16:51:25.217699218Z" level=debug msg="We can't modify the manifest, hoping for the best..." file="copy/manifest.go:137"
# time="2024-04-22 16:51:25.217846854Z" level=debug msg="Checking if we can reuse blob sha256:31603596830fc7e56753139f9c2c6bd3759e48a850659506ebfb885d1cf3aef5: general substitution = false, compression for MIME type \"application/vnd.docker.image.rootfs.diff.tar.gzip\" = true" file="copy/single.go:681"
# time="2024-04-22 16:51:25.218706444Z" level=debug msg="Failed to retrieve partial blob: convert_images not configured" file="copy/single.go:756"
# time="2024-04-22 16:51:25.218799759Z" level=debug msg="Downloading /v2/crio/alpine/blobs/sha256:31603596830fc7e56753139f9c2c6bd3759e48a850659506ebfb885d1cf3aef5" file="docker/docker_client.go:1046"
# time="2024-04-22 16:51:25.218848412Z" level=debug msg="GET https://quay.io/v2/crio/alpine/blobs/sha256:31603596830fc7e56753139f9c2c6bd3759e48a850659506ebfb885d1cf3aef5" file="docker/docker_client.go:639"
# time="2024-04-22 16:51:25.311494807Z" level=debug msg="Detected compression format gzip" file="compression/compression.go:126"
# time="2024-04-22 16:51:25.311545381Z" level=debug msg="Using original blob without modification" file="copy/compression.go:226"
# time="2024-04-22 16:51:25.311620188Z" level=debug msg="ImagePull (0): quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32 (sha256:31603596830fc7e56753139f9c2c6bd3759e48a850659506ebfb885d1cf3aef5): 0 bytes (0.00%)" file="server/image_pull.go:292" id=bd27fc67-f956-4a21-a627-dbffd5938a03 name=/runtime.v1.ImageService/PullImage
# time="2024-04-22 16:51:25.416546975Z" level=debug msg="Cached value indicated that idmapped mounts for overlay are not supported" file="overlay/overlay.go:226"
# time="2024-04-22 16:51:25.416613376Z" level=debug msg="Check for idmapped mounts support " file="overlay/overlay.go:2365"
# time="2024-04-22 16:51:25.417662412Z" level=debug msg="Applying tar in /tmp/tmp.C2aMvNzruC/crio/overlay/89ae5c4ee501a09c879f5b58474003539ab3bb978a553af2a4a6a7de248b5740/diff" file="overlay/overlay.go:2160"
# time="2024-04-22 16:51:25.491693443Z" level=debug msg="ImagePull (2): quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32 (sha256:31603596830fc7e56753139f9c2c6bd3759e48a850659506ebfb885d1cf3aef5): 2773413 bytes (100.00%)" file="server/image_pull.go:292" id=bd27fc67-f956-4a21-a627-dbffd5938a03 name=/runtime.v1.ImageService/PullImage
# time="2024-04-22 16:51:25.491761685Z" level=debug msg="No compression detected" file="compression/compression.go:133"
# time="2024-04-22 16:51:25.491834318Z" level=debug msg="Compression change for blob sha256:78a2ce922f8665f5a227dc5cd9fda87221acba8a7a952b9665f99bc771a29963 (\"application/vnd.docker.container.image.v1+json\") not supported" file="copy/compression.go:91"
# time="2024-04-22 16:51:25.491859510Z" level=debug msg="Using original blob without modification" file="copy/compression.go:226"
# time="2024-04-22 16:51:25.491992905Z" level=debug msg="ImagePull (0): quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32 (sha256:78a2ce922f8665f5a227dc5cd9fda87221acba8a7a952b9665f99bc771a29963): 0 bytes (0.00%)" file="server/image_pull.go:292" id=bd27fc67-f956-4a21-a627-dbffd5938a03 name=/runtime.v1.ImageService/PullImage
# time="2024-04-22 16:51:25.504113411Z" level=debug msg="ImagePull (2): quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32 (sha256:78a2ce922f8665f5a227dc5cd9fda87221acba8a7a952b9665f99bc771a29963): 1509 bytes (100.00%)" file="server/image_pull.go:292" id=bd27fc67-f956-4a21-a627-dbffd5938a03 name=/runtime.v1.ImageService/PullImage
# time="2024-04-22 16:51:25.504261306Z" level=debug msg="setting image creation date to 2020-04-24 01:05:35.807646609 +0000 UTC" file="storage/storage_dest.go:775"
# time="2024-04-22 16:51:25.504980876Z" level=debug msg="created new image ID \"78a2ce922f8665f5a227dc5cd9fda87221acba8a7a952b9665f99bc771a29963\" with metadata \"{}\"" file="storage/storage_dest.go:891"
# time="2024-04-22 16:51:25.505148711Z" level=debug msg="added name \"quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32\" to image \"78a2ce922f8665f5a227dc5cd9fda87221acba8a7a952b9665f99bc771a29963\"" file="storage/storage_dest.go:912"
# time="2024-04-22 16:51:25.506133861Z" level=debug msg="exporting opaque data as blob \"sha256:78a2ce922f8665f5a227dc5cd9fda87221acba8a7a952b9665f99bc771a29963\"" file="storage/storage_src.go:115"
# time="2024-04-22 16:51:25.506323360Z" level=info msg="Pulled image: quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32" file="server/image_pull.go:121" id=bd27fc67-f956-4a21-a627-dbffd5938a03 name=/runtime.v1.ImageService/PullImage
# time="2024-04-22 16:51:25.506397895Z" level=debug msg="Response: &PullImageResponse{ImageRef:quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32,}" file="otel-collector/interceptors.go:74" id=bd27fc67-f956-4a21-a627-dbffd5938a03 name=/runtime.v1.ImageService/PullImage
# time="2024-04-22 16:51:25.555275945Z" level=debug msg="Request: &VersionRequest{Version:,}" file="otel-collector/interceptors.go:62" id=1955d436-9826-4e80-ad29-fa762898279e name=/runtime.v1.RuntimeService/Version
# time="2024-04-22 16:51:25.555397110Z" level=debug msg="Response: &VersionResponse{Version:0.1.0,RuntimeName:cri-o,RuntimeVersion:1.30.0,RuntimeApiVersion:v1,}" file="otel-collector/interceptors.go:74" id=1955d436-9826-4e80-ad29-fa762898279e name=/runtime.v1.RuntimeService/Version
# time="2024-04-22 16:51:25.556317245Z" 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:[8.8.8.8],Searches:[],Options:[],},PortMappings:[]*PortMapping{},Labels:map[string]string{group: test,},Annotations:map[string]string{com.example.test: sandbox annotation,owner: hmeng,security.alpha.kubernetes.io/seccomp/pod: unconfined,},Linux:&LinuxPodSandboxConfig{CgroupParent:pod_123-456.slice,SecurityContext:&LinuxSandboxSecurityContext{NamespaceOptions:&NamespaceOption{Network:POD,Pid:CONTAINER,Ipc:POD,TargetId:,UsernsOptions:nil,},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,Seccomp:nil,Apparmor:nil,},Sysctls:map[string]string{},Overhead:nil,Resources:nil,},Windows:nil,},RuntimeHandler:,}" file="otel-collector/interceptors.go:62" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.556378675Z" level=info msg="Running pod sandbox: redhat.test.crio/podsandbox1/POD" file="server/sandbox_run_linux.go:362" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.556428592Z" level=debug msg="Initializing stage for resource k8s_podsandbox1_redhat.test.crio_redhat-test-crio_1 to sandbox creating" file="resourcestore/resourcestore.go:219" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.556464784Z" level=debug msg="Setting stage for resource k8s_podsandbox1_redhat.test.crio_redhat-test-crio_1 from sandbox creating to sandbox network ready" file="resourcestore/resourcestore.go:227" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.556497079Z" level=info msg="Allowed annotations are specified for workload []" file="config/workloads.go:120"
# time="2024-04-22 16:51:25.556526904Z" level=debug msg="Setting stage for resource k8s_podsandbox1_redhat.test.crio_redhat-test-crio_1 from sandbox network ready to sandbox storage creation" file="resourcestore/resourcestore.go:227" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.556791072Z" level=debug msg="exporting opaque data as blob \"sha256:e6f1816883972d4be47bd48879a08919b96afcd344132622e4d444987919323c\"" file="storage/storage_src.go:115"
# time="2024-04-22 16:51:25.557672332Z" level=debug msg="Created pod sandbox \"a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828\"" file="storage/runtime.go:239"
# time="2024-04-22 16:51:25.557874220Z" level=debug msg="Pod sandbox \"a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828\" has work directory \"/tmp/tmp.C2aMvNzruC/crio/overlay-containers/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/userdata\"" file="storage/runtime.go:274"
# time="2024-04-22 16:51:25.557933094Z" level=debug msg="Pod sandbox \"a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828\" has run directory \"/tmp/tmp.C2aMvNzruC/crio-run/overlay-containers/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/userdata\"" file="storage/runtime.go:284"
# time="2024-04-22 16:51:25.558458546Z" level=debug msg="Setting stage for resource k8s_podsandbox1_redhat.test.crio_redhat-test-crio_1 from sandbox storage creation to sandbox shm creation" file="resourcestore/resourcestore.go:227" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.558762660Z" level=debug msg="Setting stage for resource k8s_podsandbox1_redhat.test.crio_redhat-test-crio_1 from sandbox shm creation to sandbox spec configuration" file="resourcestore/resourcestore.go:227" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.559169057Z" level=warning msg="Failed to find memory.max at path: \"pod_123-456.slice\"" file="cgmgr/cgmgr_linux.go:128"
# time="2024-04-22 16:51:25.559318575Z" level=debug msg="Setting stage for resource k8s_podsandbox1_redhat.test.crio_redhat-test-crio_1 from sandbox spec configuration to sandbox namespace creation" file="resourcestore/resourcestore.go:227" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.559356810Z" level=debug msg="Calling pinns with [-d /var/run -f bb6c17c9-b38e-4ec2-8fd7-62b97d9cca83 --ipc --net --uts]" file="nsmgr/nsmgr_linux.go:121"
# time="2024-04-22 16:51:25.561070539Z" level=debug msg="Setting stage for resource k8s_podsandbox1_redhat.test.crio_redhat-test-crio_1 from sandbox namespace creation to sandbox network creation" file="resourcestore/resourcestore.go:227" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.561622899Z" level=info msg="Got pod network &{Name:podsandbox1 Namespace:redhat.test.crio ID:a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 UID:redhat-test-crio NetNS:/var/run/netns/bb6c17c9-b38e-4ec2-8fd7-62b97d9cca83 Networks:[] RuntimeConfig:map[crio:{IP: MAC: PortMappings:[] Bandwidth:<nil> IpRanges:[] CgroupPath:pod_123-456.slice PodAnnotations:0xc0000cc780}] Aliases:map[]}" file="ocicni/ocicni.go:810"
# time="2024-04-22 16:51:25.561686227Z" level=info msg="Adding pod redhat.test.crio_podsandbox1 to CNI network \"crio\" (type=bridge)" file="ocicni/ocicni.go:561"
# time="2024-04-22 16:51:25.648238981Z" level=info msg="Got pod network &{Name:podsandbox1 Namespace:redhat.test.crio ID:a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 UID:redhat-test-crio NetNS:/var/run/netns/bb6c17c9-b38e-4ec2-8fd7-62b97d9cca83 Networks:[] RuntimeConfig:map[crio:{IP: MAC: PortMappings:[] Bandwidth:<nil> IpRanges:[] CgroupPath:pod_123-456.slice PodAnnotations:0xc0000cc780}] Aliases:map[]}" file="ocicni/ocicni.go:810"
# time="2024-04-22 16:51:25.648381117Z" level=info msg="Checking pod redhat.test.crio_podsandbox1 for CNI network crio (type=bridge)" file="ocicni/ocicni.go:707"
# time="2024-04-22 16:51:25.648607763Z" level=debug msg="CNI setup result: &{0.3.1 [{Name:cni0 Mac:4a:a0:48:81:c2:18 Sandbox:} {Name:veth16843f72 Mac:de:eb:ba:7f:24:b0 Sandbox:} {Name:eth0 Mac:e6:05:f8:dd:6f:5a Sandbox:/var/run/netns/bb6c17c9-b38e-4ec2-8fd7-62b97d9cca83}] [{Version:4 Interface:0xc0002eb918 Address:{IP:10.88.0.84 Mask:ffff0000} Gateway:10.88.0.1} {Version:6 Interface:0xc0002eb9f8 Address:{IP:1100:200::54 Mask:ffffff00000000000000000000000000} Gateway:1100:200::1}] [{Dst:{IP:0.0.0.0 Mask:00000000} GW:<nil>} {Dst:{IP:1100:200::1 Mask:ffffff00000000000000000000000000} GW:<nil>}] {[] [] []}}" file="server/sandbox_network.go:76" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.648665302Z" level=debug msg="Found POD IPs: [10.88.0.84 1100:200::54]" file="server/sandbox_network.go:124" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.648889385Z" level=debug msg="Setting stage for resource k8s_podsandbox1_redhat.test.crio_redhat-test-crio_1 from sandbox network creation to sandbox storage start" file="resourcestore/resourcestore.go:227" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.649626513Z" level=debug msg="overlay: test mount indicated that volatile is being used" file="overlay/overlay.go:198"
# time="2024-04-22 16:51:25.649730508Z" level=debug msg="overlay: mount_data=lowerdir=/tmp/tmp.C2aMvNzruC/crio/overlay/l/TWCHGESYWTS2H5EFXRELZK6RYJ,upperdir=/tmp/tmp.C2aMvNzruC/crio/overlay/12810fc22332023f8d99a66c0e5c4204881152ada30497ba3486a225eec74413/diff,workdir=/tmp/tmp.C2aMvNzruC/crio/overlay/12810fc22332023f8d99a66c0e5c4204881152ada30497ba3486a225eec74413/work,metacopy=on,volatile,context=\"system_u:object_r:container_file_t:s0:c4,c5\"" file="overlay/overlay.go:1834"
# time="2024-04-22 16:51:25.650079590Z" level=debug msg="Mounted container \"a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828\" at \"/tmp/tmp.C2aMvNzruC/crio/overlay/12810fc22332023f8d99a66c0e5c4204881152ada30497ba3486a225eec74413/merged\"" file="storage/runtime.go:464"
# time="2024-04-22 16:51:25.650468445Z" level=debug msg="Setup seccomp from profile field: nil" file="seccomp/seccomp.go:176" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.650512621Z" level=debug msg="Evaluating seccomp annotations" file="seccompociartifact/seccompociartifact.go:44" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.650548260Z" level=debug msg="Keeping infra container for pod a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828" file="server/sandbox_run_linux.go:928" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.652092966Z" level=debug msg="Setting stage for resource k8s_podsandbox1_redhat.test.crio_redhat-test-crio_1 from sandbox storage start to sandbox container runtime creation" file="resourcestore/resourcestore.go:227" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.652172261Z" level=debug msg="oci.newRuntimeVM() start" file="oci/runtime_vm.go:83"
# time="2024-04-22 16:51:25.652211494Z" level=debug msg="oci.newRuntimeVM() end" file="oci/runtime_vm.go:98"
# time="2024-04-22 16:51:25.652259362Z" level=debug msg="RuntimeVM.CreateContainer() start" file="oci/runtime_vm.go:146" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.652316605Z" level=debug msg="RuntimeVM.startRuntimeDaemon() start" file="oci/runtime_vm.go:240" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.671659642Z" level=debug msg="RuntimeVM.startRuntimeDaemon() end" file="oci/runtime_vm.go:305" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:25.672016471Z" level=debug msg="Start writing stream \"stdout\" to log file \"/var/log/crio/pods/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828.log\"" file="io/logger.go:54"
# time="2024-04-22 16:51:25.672069613Z" level=debug msg="Start writing stream \"stderr\" to log file \"/var/log/crio/pods/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828.log\"" file="io/logger.go:54"
# time="2024-04-22T16:51:25.685503516Z" level=info msg="loading plugin \"io.containerd.event.v1.publisher\"..." runtime=io.containerd.kata.v2 type=io.containerd.event.v1
# time="2024-04-22T16:51:25.685533877Z" level=info msg="loading plugin \"io.containerd.ttrpc.v1.task\"..." runtime=io.containerd.kata.v2 type=io.containerd.ttrpc.v1
# time="2024-04-22T16:51:25.685546750Z" level=debug msg="registering ttrpc service" id=io.containerd.ttrpc.v1.task
# time="2024-04-22T16:51:25.685556819Z" level=info msg="loading plugin \"io.containerd.internal.v1.shutdown\"..." runtime=io.containerd.kata.v2 type=io.containerd.internal.v1
# time="2024-04-22T16:51:25.685674197Z" level=debug msg="serving api on socket" socket="[inherited from parent]"
# time="2024-04-22T16:51:25.685694651Z" level=info msg="starting signal loop" namespace=default path=/tmp/tmp.C2aMvNzruC/crio-run/overlay-containers/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/userdata pid=86957 runtime=io.containerd.kata.v2
# time="2024-04-22T16:51:25.685905910Z" level=debug msg="Create() start" container=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=containerd-kata-shim-v2
# time="2024-04-22T16:51:25.685987845Z" level=debug msg="converting /tmp/tmp.C2aMvNzruC/crio-run/overlay-containers/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/userdata/config.json" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=compatoci
# time="2024-04-22T16:51:25.688811125Z" level=info msg="loaded configuration" file=/opt/kata/share/defaults/kata-containers/configuration-qemu.toml format=TOML name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=katautils
# time="2024-04-22T16:51:25.688920276Z" level=info msg="IOMMUPlatform is disabled by default." name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=katautils
# time="2024-04-22T16:51:25.689039719Z" level=info msg="shm-size detected: 67108864" source=virtcontainers subsystem=oci
# time="2024-04-22T16:51:25.706145450Z" level=info msg="Set selinux=0 to kernel params because SELinux on the guest is disabled" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers/hypervisor subsystem=qemu
# time="2024-04-22T16:51:25.706736037Z" level=info msg="adding volume" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers/hypervisor subsystem=qemu volume-type=virtio-fs
# time="2024-04-22T16:51:25.707320872Z" level=info msg="veth interface found" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=network
# time="2024-04-22T16:51:25.707373768Z" level=info msg="Attaching endpoint" endpoint-type=virtual hotplug=false name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=network
# time="2024-04-22T16:51:25.707430579Z" level=info msg="connect TCFilter to VM network" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=network
# time="2024-04-22T16:51:25.715207616Z" level=info msg="endpoints found after scan" endpoints="[0xc00002a900]" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=network
# time="2024-04-22T16:51:25.738543889Z" level=info msg="Starting VM" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=sandbox
# time="2024-04-22T16:51:25.738717645Z" level=info msg="created vm path" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers/hypervisor subsystem=qemu vm path=/run/vc/vm/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828
# time="2024-04-22T16:51:25.739090024Z" level=info name=containerd-shim-v2 path=/opt/kata/libexec/virtiofsd pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers/hypervisor subsystem=virtiofsd
# time="2024-04-22T16:51:25.739132562Z" level=info args="--syslog --cache=auto --shared-dir=/run/kata-containers/shared/sandboxes/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/shared --fd=3 --thread-pool-size=1 --announce-submounts" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers/hypervisor subsystem=virtiofsd
# time="2024-04-22T16:51:25.739539965Z" level=info msg="Adding extra file [0xc000122310 0xc000122208 0xc0001222e8 0xc0001222c8]" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers/hypervisor subsystem=qmp
# time="2024-04-22T16:51:25.739626008Z" level=info msg="launching /opt/kata/bin/qemu-system-x86_64 with: [-name sandbox-a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 -uuid 3e458037-5851-43f4-b5f7-0ac9831df181 -machine q35,accel=kvm,nvdimm=on -cpu host,pmu=off -qmp unix:fd=3,server=on,wait=off -m 2048M,slots=10,maxmem=33103M -device pci-bridge,bus=pcie.0,id=pci-bridge-0,chassis_nr=1,shpc=off,addr=2,io-reserve=4k,mem-reserve=1m,pref64-reserve=1m -device virtio-serial-pci,disable-modern=true,id=serial0 -device virtconsole,chardev=charconsole0,id=console0 -chardev socket,id=charconsole0,path=/run/vc/vm/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/console.sock,server=on,wait=off -device nvdimm,id=nv0,memdev=mem0,unarmed=on -object memory-backend-file,id=mem0,mem-path=/opt/kata/share/kata-containers/kata-ubuntu-latest.image,size=268435456,readonly=on -device virtio-scsi-pci,id=scsi0,disable-modern=true -object rng-random,id=rng0,filename=/dev/urandom -device virtio-rng-pci,rng=rng0 -device vhost-vsock-pci,disable-modern=true,vhostfd=4,id=vsock-3174905814,guest-cid=3174905814 -chardev socket,id=char-63d37d288477db35,path=/run/vc/vm/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/vhost-fs.sock -device vhost-user-fs-pci,chardev=char-63d37d288477db35,tag=kataShared,queue-size=1024 -netdev tap,id=network-0,vhost=on,vhostfds=5,fds=6 -device driver=virtio-net-pci,netdev=network-0,mac=e6:05:f8:dd:6f:5a,disable-modern=true,mq=on,vectors=4 -rtc base=utc,driftfix=slew,clock=host -global kvm-pit.lost_tick_policy=discard -vga none -no-user-config -nodefaults -nographic --no-reboot -object memory-backend-file,id=dimm1,size=2048M,mem-path=/dev/shm,share=on -numa node,memdev=dimm1 -kernel /opt/kata/share/kata-containers/vmlinux-5.19.2-100 -append tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k cryptomgr.notests net.ifnames=0 pci=lastbus=0 root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro ro rootfstype=ext4 console=hvc0 console=hvc1 quiet systemd.show_status=false panic=1 nr_cpus=8 selinux=0 systemd.unit=kata-containers.target systemd.mask=systemd-networkd.service systemd.mask=systemd-networkd.socket scsi_mod.scan=none -pidfile /run/vc/vm/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/pid -smp 1,cores=1,threads=1,sockets=8,maxcpus=8]" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers/hypervisor subsystem=qmp
# time="2024-04-22T16:51:25.740440081Z" level=info msg="Start logging QEMU (qemuPid=86966)" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers/hypervisor subsystem=qemu
# time="2024-04-22T16:51:25.768318879Z" level=info msg="QMP details" name=containerd-shim-v2 pid=86957 qmp-Capabilities=oob qmp-major-version=7 qmp-micro-version=0 qmp-minor-version=2 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers/hypervisor subsystem=qemu
# time="2024-04-22T16:51:25.837242767Z" level=info msg="scanner return error: read unix @->/run/vc/vm/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/qmp.sock: use of closed network connection" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers/hypervisor subsystem=qmp
# time="2024-04-22T16:51:25.837529705Z" level=info msg="hypervisor pid is 86966" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=sandbox
# time="2024-04-22T16:51:25.838088607Z" level=info msg="already added" endpoint=eth0 name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=network
# time="2024-04-22T16:51:25.838235077Z" level=info msg="already added" endpoint=tap0_kata name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=network
# time="2024-04-22T16:51:25.838279619Z" level=info msg="endpoints found after scan" endpoints="[0xc00002a900]" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=network
# time="2024-04-22T16:51:25.838361072Z" level=info msg="VM started" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=sandbox
# time="2024-04-22T16:51:25.838451640Z" level=info msg="New client" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=kata_agent url="vsock://3174905814:1024"
# time="2024-04-22T16:51:26.950666515Z" level=info msg="Agent started in the sandbox" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=sandbox
# time="2024-04-22T16:51:26.952916594Z" level=info msg="device details" container=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 device-major=0 device-minor=112 mount-point=/tmp/tmp.C2aMvNzruC/crio/overlay/12810fc22332023f8d99a66c0e5c4204881152ada30497ba3486a225eec74413/merged name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=container
# time="2024-04-22T16:51:26.952997740Z" level=info msg="Attach devices" container=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 devices="[]" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=container
# time="2024-04-22T16:51:26.954669131Z" level=info msg="Using sandbox shm" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 shm-size=67108864 source=virtcontainers subsystem=kata_agent
# time="2024-04-22T16:51:26.955049284Z" level=info msg="Empty SELinux label for the process and the mount because guest SELinux is disabled" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=kata_agent
# time="2024-04-22T16:51:27.040957380Z" level=info msg="management server started" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=containerd-kata-shim-v2
# time="2024-04-22T16:51:27.041086403Z" level=info msg="post event: &TaskCreate{ContainerID:a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828,Bundle:/tmp/tmp.C2aMvNzruC/crio-run/overlay-containers/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/userdata,Rootfs:[]*Mount{},IO:&TaskIO{Stdin:,Stdout:/run/vc/crio/fifo/io/627955477/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828-stdout,Stderr:/run/vc/crio/fifo/io/627955477/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828-stderr,Terminal:false,XXX_unrecognized:[],},Checkpoint:,Pid:86966,XXX_unrecognized:[],}" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=containerd-kata-shim-v2 topic=/tasks/create
# time="2024-04-22T16:51:27.041241069Z" level=info msg="kata management inited" name=containerd-shim-v2 source=containerd-kata-shim-v2 subsystem=shim-management
# time="2024-04-22 16:51:27.041436383Z" level=debug msg="RuntimeVM.CreateContainer() end" file="oci/runtime_vm.go:236" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:27.041538471Z" level=debug msg="RuntimeVM.StartContainer() start" file="oci/runtime_vm.go:310" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22T16:51:27.042501717Z" level=info msg="Sandbox is started" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=sandbox
# time="2024-04-22T16:51:27.042828749Z" level=info msg="post event: &TaskStart{ContainerID:a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828,Pid:86966,XXX_unrecognized:[],}" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=containerd-kata-shim-v2 topic=/tasks/start
# time="2024-04-22 16:51:27.042940877Z" level=debug msg="RuntimeVM.StartContainer() end" file="oci/runtime_vm.go:340" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:27.043019076Z" level=debug msg="RuntimeVM.UpdateContainerStatus() start" file="oci/runtime_vm.go:730" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:27.043051463Z" level=debug msg="RuntimeVM.updateContainerStatus() start" file="oci/runtime_vm.go:744" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:27.043472285Z" level=debug msg="RuntimeVM.updateContainerStatus() end" file="oci/runtime_vm.go:818" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:27.043521275Z" level=debug msg="RuntimeVM.UpdateContainerStatus() end" file="oci/runtime_vm.go:737" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:27.043930244Z" level=info msg="Ran pod sandbox a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 with infra container: redhat.test.crio/podsandbox1/POD" file="server/sandbox_run_linux.go:1052" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:27.044180492Z" level=debug msg="Response: &RunPodSandboxResponse{PodSandboxId:a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828,}" file="otel-collector/interceptors.go:74" id=bdc0dbec-ba81-4324-8a83-d75dc87d4f0f name=/runtime.v1.RuntimeService/RunPodSandbox
# time="2024-04-22 16:51:27.045678544Z" level=debug msg="Request: &CreateContainerRequest{PodSandboxId:a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828,Config:&ContainerConfig{Metadata:&ContainerMetadata{Name:memory,Attempt:1,},Image:&ImageSpec{Image:quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32,Annotations:map[string]string{},UserSpecifiedImage:quay.io/crio/alpine@sha256:65b3a80ebe7471beecbc090c5b2cdd0aafeaefa0715f8f12e40dc918a3a70e32,RuntimeHandler:,},Command:[/bin/sh -c sleep 600],Args:[],WorkingDir:/,Envs:[]*KeyValue{&KeyValue{Key:PATH,Value:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin,},&KeyValue{Key:TERM,Value:xterm,},&KeyValue{Key:GLIBC_TUNABLES,Value:glibc.pthread.rseq=0,},&KeyValue{Key:TESTDIR,Value:test/dir1,},&KeyValue{Key:TESTFILE,Value:test/file1,},},Mounts:[]*Mount{},Devices:[]*Device{},Labels:map[string]string{batch: no,type: small,},Annotations:map[string]string{daemon: crio,owner: dragon,},LogPath:,Stdin:false,StdinOnce:false,Tty:false,Linux:&LinuxContainerConfig{Resources:&LinuxContainerResources{CpuPeriod:10000,CpuQuota:20000,CpuShares:512,MemoryLimitInBytes:12582912,OomScoreAdj:30,CpusetCpus:,CpusetMems:,HugepageLimits:[]*HugepageLimit{},Unified:map[string]string{},MemorySwapLimitInBytes:0,},SecurityContext:&LinuxContainerSecurityContext{Capabilities:&Capability{AddCapabilities:[setuid setgid],DropCapabilities:[],AddAmbientCapabilities:[],},Privileged:false,NamespaceOptions:&NamespaceOption{Network:POD,Pid:CONTAINER,Ipc:POD,TargetId:,UsernsOptions:nil,},SelinuxOptions:&SELinuxOption{User:system_u,Role:system_r,Type:svirt_lxc_net_t,Level:s0:c4,c5,},RunAsUser:&Int64Value{Value:0,},RunAsUsername:,ReadonlyRootfs:false,SupplementalGroups:[],ApparmorProfile:,SeccompProfilePath:,NoNewPrivs:false,RunAsGroup:nil,MaskedPaths:[],ReadonlyPaths:[],Seccomp:nil,Apparmor:nil,},},Windows:nil,CDIDevices:[]*CDIDevice{},},SandboxConfig:&PodSandboxConfig{Metadata:&PodSandboxMetadata{Name:podsandbox1,Uid:redhat-test-crio,Namespace:redhat.test.crio,Attempt:1,},Hostname:crictl_host,LogDirectory:,DnsConfig:&DNSConfig{Servers:[8.8.8.8],Searches:[],Options:[],},PortMappings:[]*PortMapping{},Labels:map[string]string{group: test,},Annotations:map[string]string{com.example.test: sandbox annotation,owner: hmeng,security.alpha.kubernetes.io/seccomp/pod: unconfined,},Linux:&LinuxPodSandboxConfig{CgroupParent:pod_123-456.slice,SecurityContext:&LinuxSandboxSecurityContext{NamespaceOptions:&NamespaceOption{Network:POD,Pid:CONTAINER,Ipc:POD,TargetId:,UsernsOptions:nil,},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,Seccomp:nil,Apparmor:nil,},Sysctls:map[string]string{},Overhead:nil,Resources:nil,},Windows:nil,},}" file="otel-collector/interceptors.go:62" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.045744262Z" level=info msg="Creating container: //" file="server/container_create.go:314" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.046094071Z" level=debug msg="exporting opaque data as blob \"sha256:78a2ce922f8665f5a227dc5cd9fda87221acba8a7a952b9665f99bc771a29963\"" file="storage/storage_src.go:115"
# time="2024-04-22 16:51:27.046323246Z" level=debug msg="Initializing stage for resource k8s_memory_podsandbox1_redhat.test.crio_redhat-test-crio_1 to container creating" file="resourcestore/resourcestore.go:219" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.046358943Z" level=info msg="Allowed annotations are specified for workload []" file="config/workloads.go:120"
# time="2024-04-22 16:51:27.046628610Z" level=debug msg="exporting opaque data as blob \"sha256:78a2ce922f8665f5a227dc5cd9fda87221acba8a7a952b9665f99bc771a29963\"" file="storage/storage_src.go:115"
# time="2024-04-22 16:51:27.046800856Z" level=debug msg="Setting stage for resource k8s_memory_podsandbox1_redhat.test.crio_redhat-test-crio_1 from container creating to container storage creation" file="resourcestore/resourcestore.go:227" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.046970994Z" level=debug msg="exporting opaque data as blob \"sha256:78a2ce922f8665f5a227dc5cd9fda87221acba8a7a952b9665f99bc771a29963\"" file="storage/storage_src.go:115"
# time="2024-04-22 16:51:27.047753538Z" level=debug msg="Created container \"f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f\"" file="storage/runtime.go:241"
# time="2024-04-22 16:51:27.047927327Z" level=debug msg="Container \"f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f\" has work directory \"/tmp/tmp.C2aMvNzruC/crio/overlay-containers/f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f/userdata\"" file="storage/runtime.go:276"
# time="2024-04-22 16:51:27.047996478Z" level=debug msg="Container \"f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f\" has run directory \"/tmp/tmp.C2aMvNzruC/crio-run/overlay-containers/f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f/userdata\"" file="storage/runtime.go:286"
# time="2024-04-22 16:51:27.048037501Z" level=debug msg="Setting stage for resource k8s_memory_podsandbox1_redhat.test.crio_redhat-test-crio_1 from container storage creation to container volume configuration" file="resourcestore/resourcestore.go:227" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.049391349Z" level=debug msg="Setting stage for resource k8s_memory_podsandbox1_redhat.test.crio_redhat-test-crio_1 from container volume configuration to container device creation" file="resourcestore/resourcestore.go:227" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.049445180Z" level=debug msg="Setting stage for resource k8s_memory_podsandbox1_redhat.test.crio_redhat-test-crio_1 from container device creation to container storage start" file="resourcestore/resourcestore.go:227" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.049604720Z" level=debug msg="overlay: mount_data=lowerdir=/tmp/tmp.C2aMvNzruC/crio/overlay/l/74FLGT4HXG4NQLYH3SGYNGVOPF,upperdir=/tmp/tmp.C2aMvNzruC/crio/overlay/5b61d928a80aba14f480adb3ad21c40b09d97efde3406e699de5a7db47262acc/diff,workdir=/tmp/tmp.C2aMvNzruC/crio/overlay/5b61d928a80aba14f480adb3ad21c40b09d97efde3406e699de5a7db47262acc/work,metacopy=on,volatile,context=\"system_u:object_r:container_file_t:s0:c4,c5\"" file="overlay/overlay.go:1834"
# time="2024-04-22 16:51:27.050056983Z" level=debug msg="Mounted container \"f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f\" at \"/tmp/tmp.C2aMvNzruC/crio/overlay/5b61d928a80aba14f480adb3ad21c40b09d97efde3406e699de5a7db47262acc/merged\"" file="storage/runtime.go:464"
# time="2024-04-22 16:51:27.050109813Z" level=debug msg="Setting stage for resource k8s_memory_podsandbox1_redhat.test.crio_redhat-test-crio_1 from container storage start to container spec configuration" file="resourcestore/resourcestore.go:227" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.050174354Z" level=debug msg="Setting container's log_path = /var/log/crio/pods/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828, sbox.logdir = , ctr.logfile = /var/log/crio/pods/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f.log" file="container/container.go:454"
# time="2024-04-22 16:51:27.050954822Z" level=info msg="Allowed annotations are specified for workload []" file="config/workloads.go:120"
# time="2024-04-22 16:51:27.051001542Z" level=debug msg="Setup seccomp from profile field: nil" file="seccomp/seccomp.go:176" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.051029823Z" level=debug msg="Evaluating seccomp annotations" file="seccompociartifact/seccompociartifact.go:44" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.051060449Z" level=debug msg="Setting container's log_path = /var/log/crio/pods/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828, sbox.logdir = , ctr.logfile = /var/log/crio/pods/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f.log" file="container/container.go:454"
# time="2024-04-22 16:51:27.051161828Z" level=debug msg="CONTAINER USER: 0" file="server/container_create.go:223" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.053984675Z" level=debug msg="/etc/system-fips does not exist on host, not mounting FIPS mode subscription" file="subscriptions/subscriptions.go:207"
# time="2024-04-22 16:51:27.054146863Z" level=info msg="Allowed annotations are specified for workload []" file="config/workloads.go:120"
# time="2024-04-22 16:51:27.054461175Z" level=debug msg="Setting stage for resource k8s_memory_podsandbox1_redhat.test.crio_redhat-test-crio_1 from container spec configuration to container runtime creation" file="resourcestore/resourcestore.go:227" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.054498423Z" level=debug msg="oci.newRuntimeVM() start" file="oci/runtime_vm.go:83"
# time="2024-04-22 16:51:27.054532138Z" level=debug msg="oci.newRuntimeVM() end" file="oci/runtime_vm.go:98"
# time="2024-04-22 16:51:27.054562726Z" level=debug msg="RuntimeVM.CreateContainer() start" file="oci/runtime_vm.go:146" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.054591056Z" level=debug msg="RuntimeVM.startRuntimeDaemon() start" file="oci/runtime_vm.go:240" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.072242318Z" level=debug msg="RuntimeVM.startRuntimeDaemon() end" file="oci/runtime_vm.go:305" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.072482628Z" level=debug msg="Start writing stream \"stdout\" to log file \"/var/log/crio/pods/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f.log\"" file="io/logger.go:54"
# time="2024-04-22 16:51:27.072538928Z" level=debug msg="Start writing stream \"stderr\" to log file \"/var/log/crio/pods/a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828/f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f.log\"" file="io/logger.go:54"
# time="2024-04-22T16:51:27.074238557Z" level=info msg="device details" container=f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f device-major=0 device-minor=115 mount-point=/tmp/tmp.C2aMvNzruC/crio/overlay/5b61d928a80aba14f480adb3ad21c40b09d97efde3406e699de5a7db47262acc/merged name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=container
# time="2024-04-22T16:51:27.074536584Z" level=info msg="Attach devices" container=f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f devices="[]" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=container
# time="2024-04-22T16:51:27.075356097Z" level=info msg="Using sandbox shm" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 shm-size=67108864 source=virtcontainers subsystem=kata_agent
# time="2024-04-22T16:51:27.075607488Z" level=info msg="Empty SELinux label for the process and the mount because guest SELinux is disabled" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=kata_agent
# time="2024-04-22T16:51:27.106366372Z" level=info msg="Memory Sandbox + Memory Limit " memory limit=12582912 name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=sandbox
# time="2024-04-22T16:51:27.255946959Z" level=info msg="post event: &TaskCreate{ContainerID:f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f,Bundle:/tmp/tmp.C2aMvNzruC/crio-run/overlay-containers/f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f/userdata,Rootfs:[]*Mount{},IO:&TaskIO{Stdin:,Stdout:/run/vc/crio/fifo/io/1850008726/f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f-stdout,Stderr:/run/vc/crio/fifo/io/1850008726/f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f-stderr,Terminal:false,XXX_unrecognized:[],},Checkpoint:,Pid:86966,XXX_unrecognized:[],}" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=containerd-kata-shim-v2 topic=/tasks/create
# time="2024-04-22 16:51:27.256197339Z" level=debug msg="RuntimeVM.CreateContainer() end" file="oci/runtime_vm.go:236" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.256354274Z" level=debug msg="RuntimeVM.UpdateContainerStatus() start" file="oci/runtime_vm.go:730" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.256392112Z" level=debug msg="RuntimeVM.updateContainerStatus() start" file="oci/runtime_vm.go:744" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.256743750Z" level=debug msg="RuntimeVM.updateContainerStatus() end" file="oci/runtime_vm.go:818" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.256817918Z" level=debug msg="RuntimeVM.UpdateContainerStatus() end" file="oci/runtime_vm.go:737" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.257099155Z" level=info msg="Created container f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f: //" file="server/container_create.go:491" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.257274514Z" level=debug msg="Response: &CreateContainerResponse{ContainerId:f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f,}" file="otel-collector/interceptors.go:74" id=507b129b-ff9b-40c2-ab12-44e14f87cebc name=/runtime.v1.RuntimeService/CreateContainer
# time="2024-04-22 16:51:27.258034618Z" level=debug msg="Request: &StartContainerRequest{ContainerId:f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f,}" file="otel-collector/interceptors.go:62" id=268399da-b66b-4103-bd55-a6347e6faca1 name=/runtime.v1.RuntimeService/StartContainer
# time="2024-04-22 16:51:27.258076763Z" level=info msg="Starting container: f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f" file="server/container_start.go:21" id=268399da-b66b-4103-bd55-a6347e6faca1 name=/runtime.v1.RuntimeService/StartContainer
# time="2024-04-22 16:51:27.258193474Z" level=debug msg="RuntimeVM.StartContainer() start" file="oci/runtime_vm.go:310" id=268399da-b66b-4103-bd55-a6347e6faca1 name=/runtime.v1.RuntimeService/StartContainer
# time="2024-04-22T16:51:27.260879651Z" level=info msg="Container is started" container=f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=sandbox
# time="2024-04-22T16:51:27.260973792Z" level=info msg="Memory Sandbox + Memory Limit " memory limit=12582912 name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers subsystem=sandbox
# time="2024-04-22T16:51:27.261117171Z" level=warning msg="hot-remove VM memory not supported" hotplug=memory name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=virtcontainers/hypervisor subsystem=qemu
# time="2024-04-22 16:51:27.263996812Z" level=debug msg="RuntimeVM.StartContainer() end" file="oci/runtime_vm.go:340" id=268399da-b66b-4103-bd55-a6347e6faca1 name=/runtime.v1.RuntimeService/StartContainer
# time="2024-04-22T16:51:27.263955983Z" level=info msg="post event: &TaskStart{ContainerID:f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f,Pid:86966,XXX_unrecognized:[],}" name=containerd-shim-v2 pid=86957 sandbox=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828 source=containerd-kata-shim-v2 topic=/tasks/start
# time="2024-04-22 16:51:27.264160296Z" level=info msg="Started container" PID=86966 containerID=f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f description=// file="server/container_start.go:115" id=268399da-b66b-4103-bd55-a6347e6faca1 name=/runtime.v1.RuntimeService/StartContainer sandboxID=a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828
# time="2024-04-22 16:51:27.264223644Z" level=debug msg="RuntimeVM.UpdateContainerStatus() start" file="oci/runtime_vm.go:730" id=268399da-b66b-4103-bd55-a6347e6faca1 name=/runtime.v1.RuntimeService/StartContainer
# time="2024-04-22 16:51:27.264256196Z" level=debug msg="RuntimeVM.updateContainerStatus() start" file="oci/runtime_vm.go:744" id=268399da-b66b-4103-bd55-a6347e6faca1 name=/runtime.v1.RuntimeService/StartContainer
# time="2024-04-22 16:51:27.264497301Z" level=debug msg="RuntimeVM.updateContainerStatus() end" file="oci/runtime_vm.go:818" id=268399da-b66b-4103-bd55-a6347e6faca1 name=/runtime.v1.RuntimeService/StartContainer
# time="2024-04-22 16:51:27.264540711Z" level=debug msg="RuntimeVM.UpdateContainerStatus() end" file="oci/runtime_vm.go:737" id=268399da-b66b-4103-bd55-a6347e6faca1 name=/runtime.v1.RuntimeService/StartContainer
# time="2024-04-22 16:51:27.264695681Z" level=debug msg="Response: &StartContainerResponse{}" file="otel-collector/interceptors.go:74" id=268399da-b66b-4103-bd55-a6347e6faca1 name=/runtime.v1.RuntimeService/StartContainer
# # --- --- ---
# f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f
# f0b894c92ead47bdeffc3e64066d8631b22bfa7edc679156b8843283acf82d6f
# Stopped sandbox a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828
# Removed sandbox a6874370a0af493ec80297a7642d67f218af1d1faab49426515ac0483f8df828
ok 217 run container with container_min_memory 5.5MiB |
|
cc @littlejawa |
This was referenced Apr 29, 2024
|
/reopen |
|
@roman-kiselenko: Reopened this issue. In response to this:
Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. |
roman-kiselenko
changed the title
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Which jobs are failing?
Which tests are failing?
The tests below failed on the
kataruntime:kata_skip_image_testscri-o/contrib/test/ci/vars.yml
Lines 157 to 161 in 6fdfd95
Since when has it been failing?
This issue is for tracking the status of failed tests. Those tests are disabled after merge:
Testgrid link
No response
Reason for failure (if possible)
Unknown
Anything else we need to know?
There's already a #7958 to test the new version of Kata.
The text was updated successfully, but these errors were encountered: