Skip to content
This repository was archived by the owner on May 12, 2021. It is now read-only.
This repository was archived by the owner on May 12, 2021. It is now read-only.

"context deadline exceeded" when deleting a pod using openshift #197

Closed
Closed
"context deadline exceeded" when deleting a pod using openshift#197
Assignees
sboeuf
@chavafg

Description

@chavafg
chavafg
opened on Apr 10, 2018

Description of problem

When trying Openshift using CRI-O and Kata-Containers, I can launch workloads, but when trying to delete a pod using:

$ sudo -E oc delete pod hello-openshift
pod "hello-openshift" deleted

I see context deadline exceeded errors in the logs:

Apr 10 19:00:29 openshift-test kata-runtime[9275]: time="2018-04-10T19:00:29.881459892Z" level=info msg="Container already stopped" arch=amd64 container-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a name=kata-runtime pid=9275 pod-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a source=virtcontainers subsystem=container
Apr 10 19:00:34 openshift-test kata-runtime[9275]: time="2018-04-10T19:00:34.881763723Z" level=error msg="context deadline exceeded" command=delete name=kata-runtime pid=9275 source=runtime
Apr 10 19:01:34 openshift-test kata-runtime[9552]: time="2018-04-10T19:01:34.895410205Z" level=debug msg="loaded configuration" command=delete format=TOML name=kata-runtime pid=9552 source=runtime
Apr 10 19:01:34 openshift-test kata-runtime[9552]: time="2018-04-10T19:01:34.895654206Z" level=info arguments="\"delete --force 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a\"" command=delete commit=59328030882945ef2026ea9a3da40bad0b4db472 name=kata-runtime pid=9552 source=runtime version=0.1.0

Also, after deleting the pod, kata-runtime list does not work correctly.

$ sudo kata-runtime list
stat /var/lib/containers/storage/devicemapper/mnt/3b81990183f99f803b18421317a8cf93d76b870c39d14a9a9d03fb76d2f7d93e/rootfs: no such file or directory

Expected result

Pod should be removed correctly

Actual result

Pod is not deleted correctly.
kata-runtime list does not work correctly.

Logs

Openshift node log:

E0410 19:22:15.254069    4577 remote_runtime.go:131] RemovePodSandbox "58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a" from runtime service failed: rpc error: code = 2 desc = failed to delete container k8s_POD_hello-openshift_default_92c7c393-3cef-11e8-a633-000d3afd2cb5_0 in pod sandbox 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a: `/usr/local/bin/kata-runtime delete --force 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a` failed: context deadline exceeded
  (exit status 1)
E0410 19:22:15.254116    4577 kuberuntime_gc.go:156] Failed to remove sandbox "58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a": rpc error: code = 2 desc = failed to delete container k8s_POD_hello-openshift_default_92c7c393-3cef-11e8-a633-000d3afd2cb5_0 in pod sandbox 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a: `/usr/local/bin/kata-runtime delete --force 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a` failed: context deadline exceeded
  (exit status 1)

CRI-O Logs:

Apr 10 18:59:47 openshift-test crio[4473]: ount{ContainerPath:/dev/termination-log,HostPath:/home/fuentess/go/src/github.com/kata-containers/tests/integration/openshift/openshift.local.volumes/pods/92c7c393-3cef
-11e8-a633-000d3afd2cb5/containers/hello-openshift/469e9463,Readonly:false,SelinuxRelabel:false,Propagation:PROPAGATION_PRIVATE,}],LogPath:,},Info:map[string]string{},}"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.351889607Z" level=debug msg="RemoveContainerRequest: &RemoveContainerRequest{ContainerId:dca6febc05d996125ea87bac34aa86241a652e6d4ad82632d59a2
3148f12eae9,}"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.367557161Z" level=debug msg="StopContainerResponse dca6febc05d996125ea87bac34aa86241a652e6d4ad82632d59a23148f12eae9: &StopContainerResponse{}"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.370281370Z" level=debug msg="devmapper: DeleteDevice START(hash=e21309cfc2ef674ae284ed2546276a06e7fec5b9adb0bdc3219e386dadd45cc3 syncDelete=fa
lse)"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.370341670Z" level=debug msg="devmapper: issueDiscard START(device: e21309cfc2ef674ae284ed2546276a06e7fec5b9adb0bdc3219e386dadd45cc3)."
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.370356270Z" level=debug msg="devmapper: activateDeviceIfNeeded(e21309cfc2ef674ae284ed2546276a06e7fec5b9adb0bdc3219e386dadd45cc3)"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.370396571Z" level=debug msg="StopPodSandboxRequest &StopPodSandboxRequest{PodSandboxId:58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47
d13c8246a,}"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.370443371Z" level=info msg="Got pod network {Name:hello-openshift Namespace:default ID:58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47
d13c8246a NetNS:/var/run/netns/k8s_hello-openshift_default_92c7c393-3cef-11e8-a633-000d3afd2cb5_0-6eac9e89 PortMappings:[]}"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.370464371Z" level=info msg="About to del CNI network mynet (type=bridge)"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.370748472Z" level=debug msg="event: "/var/run/crio/exits/dca6febc05d996125ea87bac34aa86241a652e6d4ad82632d59a23148f12eae9": REMOVE"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.439169608Z" level=debug msg="event: "/var/run/crio/exits/58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a.WVW7GZ": CREATE"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.439195609Z" level=debug msg="container or sandbox exited: 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a.WVW7GZ"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.439226709Z" level=debug msg="event: "/var/run/crio/exits/58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a.WVW7GZ": RENAME"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.439425709Z" level=debug msg="event: "/var/run/crio/exits/58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a": CREATE"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.439443709Z" level=debug msg="container or sandbox exited: 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.439456309Z" level=debug msg="sandbox exited and found: 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.722096087Z" level=debug msg="devmapper: issueDiscard END(device: e21309cfc2ef674ae284ed2546276a06e7fec5b9adb0bdc3219e386dadd45cc3)."
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.722446188Z" level=debug msg="devmapper: deactivateDevice START(e21309cfc2ef674ae284ed2546276a06e7fec5b9adb0bdc3219e386dadd45cc3)"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.722820490Z" level=debug msg="devmapper: removeDevice START(container-8:1-1285808-e21309cfc2ef674ae284ed2546276a06e7fec5b9adb0bdc3219e386dadd45
cc3)"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.759658217Z" level=debug msg="devmapper: removeDevice END(container-8:1-1285808-e21309cfc2ef674ae284ed2546276a06e7fec5b9adb0bdc3219e386dadd45cc
3)"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.759683517Z" level=debug msg="devmapper: deactivateDevice END(e21309cfc2ef674ae284ed2546276a06e7fec5b9adb0bdc3219e386dadd45cc3)"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.845801415Z" level=debug msg="ListPodSandboxRequest &ListPodSandboxRequest{Filter:&PodSandboxFilter{Id:,State:&PodSandboxStateValue{State:SANDB
OX_READY,},LabelSelector:map[string]string{},},}"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.917682164Z" level=debug msg="devmapper: unregisterDevice(e21309cfc2ef674ae284ed2546276a06e7fec5b9adb0bdc3219e386dadd45cc3)"
Apr 10 18:59:47 openshift-test crio[4473]: time="2018-04-10 18:59:47.925631091Z" level=debug msg="devmapper: DeleteDevice END(hash=e21309cfc2ef674ae284ed2546276a06e7fec5b9adb0bdc3219e386dadd45cc3 syncDelete=fals
e)"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.028076945Z" level=debug msg="RemoveContainerResponse: &RemoveContainerResponse{}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.052716131Z" level=debug msg="ListPodSandboxResponse &ListPodSandboxResponse{Items:[],}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.053154532Z" level=debug msg="ListContainersRequest &ListContainersRequest{Filter:&ContainerFilter{Id:,State:&ContainerStateValue{State:CONTAIN
ER_RUNNING,},PodSandboxId:,LabelSelector:map[string]string{},},}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.053190032Z" level=debug msg="ListContainersResponse: &ListContainersResponse{Containers:[],}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.063446768Z" level=debug msg="devmapper: UnmountDevice START(hash=3b81990183f99f803b18421317a8cf93d76b870c39d14a9a9d03fb76d2f7d93e)"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.063478468Z" level=debug msg="devmapper: Unmount(/var/lib/containers/storage/devicemapper/mnt/3b81990183f99f803b18421317a8cf93d76b870c39d14a9a9
d03fb76d2f7d93e)"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.132364206Z" level=debug msg="devmapper: Unmount done"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.132407106Z" level=debug msg="devmapper: deactivateDevice START(3b81990183f99f803b18421317a8cf93d76b870c39d14a9a9d03fb76d2f7d93e)"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.132490706Z" level=debug msg="devmapper: removeDevice START(container-8:1-1285808-3b81990183f99f803b18421317a8cf93d76b870c39d14a9a9d03fb76d2f7d
93e)"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.171648642Z" level=debug msg="devmapper: removeDevice END(container-8:1-1285808-3b81990183f99f803b18421317a8cf93d76b870c39d14a9a9d03fb76d2f7d93
e)"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.172239344Z" level=debug msg="devmapper: deactivateDevice END(3b81990183f99f803b18421317a8cf93d76b870c39d14a9a9d03fb76d2f7d93e)"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.172259044Z" level=debug msg="devmapper: UnmountDevice END(hash=3b81990183f99f803b18421317a8cf93d76b870c39d14a9a9d03fb76d2f7d93e)"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.186580093Z" level=debug msg="unmounted container "58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a""
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.186613393Z" level=debug msg="StopPodSandboxResponse 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a: &StopPodSandboxResponse{
}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.349935158Z" level=debug msg="ListPodSandboxRequest &ListPodSandboxRequest{Filter:nil,}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.349999558Z" level=debug msg="ListPodSandboxResponse &ListPodSandboxResponse{Items:[&PodSandbox{Id:58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271
090f227dc47d13c8246a,Metadata:&PodSandboxMetadata{Name:hello-openshift,Uid:92c7c393-3cef-11e8-a633-000d3afd2cb5,Namespace:default,Attempt:0,},State:SANDBOX_NOTREADY,CreatedAt:1523386034523581480,Labels:map[strin
g]string{io.kubernetes.container.name: POD,io.kubernetes.pod.name: hello-openshift,io.kubernetes.pod.namespace: default,io.kubernetes.pod.uid: 92c7c393-3cef-11e8-a633-000d3afd2cb5,name: hello-openshift,},Annotat
ions:map[string]string{io.kubernetes.cri-o.TrustedSandbox: false,kubernetes.io/config.seen: 2018-04-10T18:47:09.29505955Z,kubernetes.io/config.source: api,openshift.io/scc: anyuid,},}],}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.350411660Z" level=debug msg="ListContainersRequest &ListContainersRequest{Filter:&ContainerFilter{Id:,State:nil,PodSandboxId:,LabelSelector:ma
p[string]string{},},}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.350431560Z" level=debug msg="ListContainersResponse: &ListContainersResponse{Containers:[],}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.350778561Z" level=debug msg="ListPodSandboxRequest &ListPodSandboxRequest{Filter:&PodSandboxFilter{Id:,State:nil,LabelSelector:map[string]stri
ng{io.kubernetes.pod.uid: 92c7c393-3cef-11e8-a633-000d3afd2cb5,},},}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.350824861Z" level=debug msg="ListPodSandboxResponse &ListPodSandboxResponse{Items:[&PodSandbox{Id:58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271
090f227dc47d13c8246a,Metadata:&PodSandboxMetadata{Name:hello-openshift,Uid:92c7c393-3cef-11e8-a633-000d3afd2cb5,Namespace:default,Attempt:0,},State:SANDBOX_NOTREADY,CreatedAt:1523386034523581480,Labels:map[strin
g]string{io.kubernetes.container.name: POD,io.kubernetes.pod.name: hello-openshift,io.kubernetes.pod.namespace: default,io.kubernetes.pod.uid: 92c7c393-3cef-11e8-a633-000d3afd2cb5,name: hello-openshift,},Annotat
ions:map[string]string{io.kubernetes.cri-o.TrustedSandbox: false,kubernetes.io/config.seen: 2018-04-10T18:47:09.29505955Z,kubernetes.io/config.source: api,openshift.io/scc: anyuid,},}],}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.351097962Z" level=debug msg="PodSandboxStatusRequest &PodSandboxStatusRequest{PodSandboxId:58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227
dc47d13c8246a,Verbose:false,}"
Apr 10 18:59:48 openshift-test crio[4473]: time="2018-04-10 18:59:48.351157262Z" level=debug msg="PodSandboxStatusResponse: &PodSandboxStatusResponse{Status:&PodSandboxStatus{Id:58b5cb85d95895239edc9fd0d0ba67c9b
ad5c28e6271090f227dc47d13c8246a,Metadata:&PodSandboxMetadata{Name:hello-openshift,Uid:92c7c393-3cef-11e8-a633-000d3afd2cb5,Namespace:default,Attempt:0,},State:SANDBOX_NOTREADY,CreatedAt:1523386034523581480,Netwo
rk:&PodSandboxNetworkStatus{Ip:10.88.0.3,},Linux:nil,Labels:map[string]string{io.kubernetes.container.name: POD,io.kubernetes.pod.name: hello-openshift,io.kubernetes.pod.namespace: default,io.kubernetes.pod.uid:
 92c7c393-3cef-11e8-a633-000d3afd2cb5,name: hello-openshift,},Annotations:map[string]string{io.kubernetes.cri-o.TrustedSandbox: false,kubernetes.io/config.seen: 2018-04-10T18:47:09.29505955Z,kubernetes.io/config
.source: api,openshift.io/scc: anyuid,},},Info:map[string]string{},}"

Kata runtime log:

Apr 10 18:59:47 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:47.426600565Z" level=debug msg="loaded configuration" command=kill format=TOML name=kata-runtime pid=9056 source=runtime
Apr 10 18:59:47 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:47.427034467Z" level=info arguments="\"kill 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a TERM\"" command=kill commit=
59328030882945ef2026ea9a3da40bad0b4db472 name=kata-runtime pid=9056 source=runtime version=0.1.0
Apr 10 18:59:47 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:47.429522075Z" level=info msg="Virtual endpoint unmarshalled [{{308bcf59-a117-4bf5-b6c0-820e49367f76 br0 {eth0 02:00:ca:fe:00:00 [10.88.0
.3/16 eth0]} {tap0 e6:36:b6:18:d7:d1 []} 2 [0xc42000e1b8 0xc42000e1c8 0xc42000e1d0 0xc42000e1d8 0xc42000e1e0 0xc42000e1e8 0xc42000e1f0 0xc42000e1f8] [0xc42000e200 0xc42000e208 0xc42000e210 0xc42000e218 0xc42000e
220 0xc42000e228 0xc42000e230 0xc42000e238]} {{{3 1500 0 eth0 e6:36:b6:18:d7:d1 up|broadcast|multicast 69699 5 0 <nil>  0xc420174240 0 0xc4200756a0 ether <nil> up 0 0 0} veth} [10.88.0.3/16 eth0 fe80::e436:b6ff:
fe18:d7d1/64] [{Ifindex: 3 Dst: <nil> Src: <nil> Gw: 10.88.0.1 Flags: [] Table: 254} {Ifindex: 3 Dst: 10.88.0.0/16 Src: 10.88.0.3 Gw: <nil> Flags: [] Table: 254} {Ifindex: 3 Dst: fe80::/64 Src: <nil> Gw: <nil> F
lags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=9056 source=virtcontainers
Apr 10 18:59:47 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:47.431430882Z" level=info msg="Virtual endpoint unmarshalled [{{308bcf59-a117-4bf5-b6c0-820e49367f76 br0 {eth0 02:00:ca:fe:00:00 [10.88.0
.3/16 eth0]} {tap0 e6:36:b6:18:d7:d1 []} 2 [0xc42000e2f0 0xc42000e2f8 0xc42000e300 0xc42000e308 0xc42000e310 0xc42000e318 0xc42000e320 0xc42000e328] [0xc42000e330 0xc42000e338 0xc42000e340 0xc42000e348 0xc42000e
350 0xc42000e358 0xc42000e360 0xc42000e368]} {{{3 1500 0 eth0 e6:36:b6:18:d7:d1 up|broadcast|multicast 69699 5 0 <nil>  0xc420174600 0 0xc420075de0 ether <nil> up 0 0 0} veth} [10.88.0.3/16 eth0 fe80::e436:b6ff:
fe18:d7d1/64] [{Ifindex: 3 Dst: <nil> Src: <nil> Gw: 10.88.0.1 Flags: [] Table: 254} {Ifindex: 3 Dst: 10.88.0.0/16 Src: 10.88.0.3 Gw: <nil> Flags: [] Table: 254} {Ifindex: 3 Dst: fe80::/64 Src: <nil> Gw: <nil> F
lags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=9056 source=virtcontainers
Apr 10 18:59:47 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:47.441579717Z" level=info msg="Virtual endpoint unmarshalled [{{308bcf59-a117-4bf5-b6c0-820e49367f76 br0 {eth0 02:00:ca:fe:00:00 [10.88.0
.3/16 eth0]} {tap0 e6:36:b6:18:d7:d1 []} 2 [0xc420290050 0xc420290058 0xc420290060 0xc420290068 0xc420290070 0xc420290078 0xc420290080 0xc420290088] [0xc420290090 0xc420290098 0xc4202900a0 0xc4202900a8 0xc420290
0b0 0xc4202900b8 0xc4202900c0 0xc4202900c8]} {{{3 1500 0 eth0 e6:36:b6:18:d7:d1 up|broadcast|multicast 69699 5 0 <nil>  0xc4202c2180 0 0xc4202784c0 ether <nil> up 0 0 0} veth} [10.88.0.3/16 eth0 fe80::e436:b6ff:
fe18:d7d1/64] [{Ifindex: 3 Dst: <nil> Src: <nil> Gw: 10.88.0.1 Flags: [] Table: 254} {Ifindex: 3 Dst: 10.88.0.0/16 Src: 10.88.0.3 Gw: <nil> Flags: [] Table: 254} {Ifindex: 3 Dst: fe80::/64 Src: <nil> Gw: <nil> F
lags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=9056 source=virtcontainers
Apr 10 18:59:48 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:48.011279487Z" level=info msg="unplugging block device" arch=amd64 container-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d1
3c8246a name=kata-runtime pid=9056 pod-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a source=virtcontainers subsystem=container
Apr 10 18:59:48 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:48.011443688Z" level=info msg="Unplugging block device" arch=amd64 container-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d1
3c8246a device-id=drive-58b5cb85d95895239edc9fd0d name=kata-runtime pid=9056 pod-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a source=virtcontainers subsystem=container
Apr 10 18:59:48 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:48.011855489Z" level=info msg="{\"QMP\": {\"version\": {\"qemu\": {\"micro\": 1, \"minor\": 11, \"major\": 2}, \"package\": \" (v2.11.1-d
irty)\"}, \"capabilities\": []}}" arch=amd64 name=kata-runtime pid=9056 source=virtcontainers subsystem=qmp
Apr 10 18:59:48 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:48.01213219Z" level=info msg="{\"execute\":\"qmp_capabilities\"}" arch=amd64 name=kata-runtime pid=9056 source=virtcontainers subsystem=q
mp
Apr 10 18:59:48 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:48.013092394Z" level=info msg="{\"return\": {}}" arch=amd64 name=kata-runtime pid=9056 source=virtcontainers subsystem=qmp
Apr 10 18:59:48 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:48.013644495Z" level=info msg="{\"arguments\":{\"id\":\"virtio-drive-58b5cb85d95895239edc9fd0d\"},\"execute\":\"device_del\"}" arch=amd64
 name=kata-runtime pid=9056 source=virtcontainers subsystem=qmp
Apr 10 18:59:48 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:48.015972004Z" level=info msg="{\"timestamp\": {\"seconds\": 1523386788, \"microseconds\": 15806}, \"event\": \"DEVICE_DELETED\", \"data\
": {\"device\": \"virtio-drive-58b5cb85d95895239edc9fd0d\", \"path\": \"/machine/peripheral/virtio-drive-58b5cb85d95895239edc9fd0d\"}}" arch=amd64 name=kata-runtime pid=9056 source=virtcontainers subsystem=qmp
Apr 10 18:59:48 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:48.016441205Z" level=info msg="{\"return\": {}}" arch=amd64 name=kata-runtime pid=9056 source=virtcontainers subsystem=qmp
Apr 10 18:59:48 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:48.016883007Z" level=info msg="{\"arguments\":{\"node-name\":\"drive-58b5cb85d95895239edc9fd0d\"},\"execute\":\"blockdev-del\"}" arch=amd
64 name=kata-runtime pid=9056 source=virtcontainers subsystem=qmp
Apr 10 18:59:48 openshift-test kata-runtime[9056]: time="2018-04-10T18:59:48.022047025Z" level=info msg="{\"return\": {}}" arch=amd64 name=kata-runtime pid=9056 source=virtcontainers subsystem=qmp
Apr 10 18:59:48 openshift-test kata-runtime[9075]: time="2018-04-10T18:59:48.036938376Z" level=debug msg="loaded configuration" command=state format=TOML name=kata-runtime pid=9075 source=runtime
Apr 10 18:59:48 openshift-test kata-runtime[9075]: time="2018-04-10T18:59:48.037227277Z" level=info arguments="\"state 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a\"" command=state commit=593
28030882945ef2026ea9a3da40bad0b4db472 name=kata-runtime pid=9075 source=runtime version=0.1.0
Apr 10 18:59:48 openshift-test kata-runtime[9075]: time="2018-04-10T18:59:48.039496985Z" level=info msg="Virtual endpoint unmarshalled [{{308bcf59-a117-4bf5-b6c0-820e49367f76 br0 {eth0 02:00:ca:fe:00:00 [10.88.0
.3/16 eth0]} {tap0 e6:36:b6:18:d7:d1 []} 2 [0xc4201cc158 0xc4201cc168 0xc4201cc170 0xc4201cc178 0xc4201cc180 0xc4201cc188 0xc4201cc190 0xc4201cc198] [0xc4201cc1a0 0xc4201cc1a8 0xc4201cc1b0 0xc4201cc1b8 0xc4201cc
1c0 0xc4201cc1c8 0xc4201cc1d0 0xc4201cc1d8]} {{{3 1500 0 eth0 e6:36:b6:18:d7:d1 up|broadcast|multicast 69699 5 0 <nil>  0xc420242180 0 0xc4201b3160 ether <nil> up 0 0 0} veth} [10.88.0.3/16 eth0 fe80::e436:b6ff:
fe18:d7d1/64] [{Ifindex: 3 Dst: <nil> Src: <nil> Gw: 10.88.0.1 Flags: [] Table: 254} {Ifindex: 3 Dst: 10.88.0.0/16 Src: 10.88.0.3 Gw: <nil> Flags: [] Table: 254} {Ifindex: 3 Dst: fe80::/64 Src: <nil> Gw: <nil> F
lags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=9075 source=virtcontainers
Apr 10 18:59:48 openshift-test kata-runtime[9082]: time="2018-04-10T18:59:48.047109311Z" level=debug msg="loaded configuration" command=state format=TOML name=kata-runtime pid=9082 source=runtime
Apr 10 18:59:48 openshift-test kata-runtime[9082]: time="2018-04-10T18:59:48.047456212Z" level=info arguments="\"state 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a\"" command=state commit=593
28030882945ef2026ea9a3da40bad0b4db472 name=kata-runtime pid=9082 source=runtime version=0.1.0
Apr 10 18:59:48 openshift-test kata-runtime[9082]: time="2018-04-10T18:59:48.050310322Z" level=info msg="Virtual endpoint unmarshalled [{{308bcf59-a117-4bf5-b6c0-820e49367f76 br0 {eth0 02:00:ca:fe:00:00 [10.88.0
.3/16 eth0]} {tap0 e6:36:b6:18:d7:d1 []} 2 [0xc42000e1c0 0xc42000e1d0 0xc42000e1d8 0xc42000e1e0 0xc42000e1e8 0xc42000e1f0 0xc42000e1f8 0xc42000e200] [0xc42000e208 0xc42000e210 0xc42000e218 0xc42000e220 0xc42000e
228 0xc42000e230 0xc42000e238 0xc42000e240]} {{{3 1500 0 eth0 e6:36:b6:18:d7:d1 up|broadcast|multicast 69699 5 0 <nil>  0xc420174240 0 0xc4200756a0 ether <nil> up 0 0 0} veth} [10.88.0.3/16 eth0 fe80::e436:b6ff:
fe18:d7d1/64] [{Ifindex: 3 Dst: <nil> Src: <nil> Gw: 10.88.0.1 Flags: [] Table: 254} {Ifindex: 3 Dst: 10.88.0.0/16 Src: 10.88.0.3 Gw: <nil> Flags: [] Table: 254} {Ifindex: 3 Dst: fe80::/64 Src: <nil> Gw: <nil> F
lags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=9082 source=virtcontainers
Apr 10 19:00:29 openshift-test kata-runtime[9275]: time="2018-04-10T19:00:29.876299875Z" level=debug msg="loaded configuration" command=delete format=TOML name=kata-runtime pid=9275 source=runtime
Apr 10 19:00:29 openshift-test kata-runtime[9275]: time="2018-04-10T19:00:29.876549976Z" level=info arguments="\"delete --force 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a\"" command=delete
commit=59328030882945ef2026ea9a3da40bad0b4db472 name=kata-runtime pid=9275 source=runtime version=0.1.0
Apr 10 19:00:29 openshift-test kata-runtime[9275]: time="2018-04-10T19:00:29.879083284Z" level=info msg="Virtual endpoint unmarshalled [{{308bcf59-a117-4bf5-b6c0-820e49367f76 br0 {eth0 02:00:ca:fe:00:00 [10.88.0
.3/16 eth0]} {tap0 e6:36:b6:18:d7:d1 []} 2 [0xc4201b2160 0xc4201b2170 0xc4201b2178 0xc4201b2180 0xc4201b2188 0xc4201b2190 0xc4201b2198 0xc4201b21a0] [0xc4201b21a8 0xc4201b21b0 0xc4201b21b8 0xc4201b21c0 0xc4201b2
1c8 0xc4201b21d0 0xc4201b21d8 0xc4201b21e0]} {{{3 1500 0 eth0 e6:36:b6:18:d7:d1 up|broadcast|multicast 69699 5 0 <nil>  0xc420222180 0 0xc420197160 ether <nil> up 0 0 0} veth} [10.88.0.3/16 eth0 fe80::e436:b6ff:
fe18:d7d1/64] [{Ifindex: 3 Dst: <nil> Src: <nil> Gw: 10.88.0.1 Flags: [] Table: 254} {Ifindex: 3 Dst: 10.88.0.0/16 Src: 10.88.0.3 Gw: <nil> Flags: [] Table: 254} {Ifindex: 3 Dst: fe80::/64 Src: <nil> Gw: <nil> F
lags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=9275 source=virtcontainers
Apr 10 19:00:29 openshift-test kata-runtime[9275]: time="2018-04-10T19:00:29.881131491Z" level=info msg="Virtual endpoint unmarshalled [{{308bcf59-a117-4bf5-b6c0-820e49367f76 br0 {eth0 02:00:ca:fe:00:00 [10.88.0
.3/16 eth0]} {tap0 e6:36:b6:18:d7:d1 []} 2 [0xc4201b22a0 0xc4201b22a8 0xc4201b22b0 0xc4201b22b8 0xc4201b22c0 0xc4201b22c8 0xc4201b22d0 0xc4201b22d8] [0xc4201b22e0 0xc4201b22e8 0xc4201b22f0 0xc4201b22f8 0xc4201b2
300 0xc4201b2308 0xc4201b2310 0xc4201b2318]} {{{3 1500 0 eth0 e6:36:b6:18:d7:d1 up|broadcast|multicast 69699 5 0 <nil>  0xc420222540 0 0xc420197ca0 ether <nil> up 0 0 0} veth} [10.88.0.3/16 eth0 fe80::e436:b6ff:
fe18:d7d1/64] [{Ifindex: 3 Dst: <nil> Src: <nil> Gw: 10.88.0.1 Flags: [] Table: 254} {Ifindex: 3 Dst: 10.88.0.0/16 Src: 10.88.0.3 Gw: <nil> Flags: [] Table: 254} {Ifindex: 3 Dst: fe80::/64 Src: <nil> Gw: <nil> F
lags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=9275 source=virtcontainers
Apr 10 19:00:29 openshift-test kata-runtime[9275]: time="2018-04-10T19:00:29.881459892Z" level=info msg="Container already stopped" arch=amd64 container-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47
d13c8246a name=kata-runtime pid=9275 pod-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a source=virtcontainers subsystem=container
Apr 10 19:00:34 openshift-test kata-runtime[9275]: time="2018-04-10T19:00:34.881763723Z" level=error msg="context deadline exceeded" command=delete name=kata-runtime pid=9275 source=runtime
Apr 10 19:01:34 openshift-test kata-runtime[9552]: time="2018-04-10T19:01:34.895410205Z" level=debug msg="loaded configuration" command=delete format=TOML name=kata-runtime pid=9552 source=runtime
Apr 10 19:01:34 openshift-test kata-runtime[9552]: time="2018-04-10T19:01:34.895654206Z" level=info arguments="\"delete --force 58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a\"" command=delete
commit=59328030882945ef2026ea9a3da40bad0b4db472 name=kata-runtime pid=9552 source=runtime version=0.1.0
Apr 10 19:01:34 openshift-test kata-runtime[9552]: time="2018-04-10T19:01:34.897685513Z" level=info msg="Virtual endpoint unmarshalled [{{308bcf59-a117-4bf5-b6c0-820e49367f76 br0 {eth0 02:00:ca:fe:00:00 [10.88.0
.3/16 eth0]} {tap0 e6:36:b6:18:d7:d1 []} 2 [0xc4201b8160 0xc4201b8170 0xc4201b8178 0xc4201b8180 0xc4201b8188 0xc4201b8190 0xc4201b8198 0xc4201b81a0] [0xc4201b81a8 0xc4201b81b0 0xc4201b81b8 0xc4201b81c0 0xc4201b8
1c8 0xc4201b81d0 0xc4201b81d8 0xc4201b81e0]} {{{3 1500 0 eth0 e6:36:b6:18:d7:d1 up|broadcast|multicast 69699 5 0 <nil>  0xc420228180 0 0xc42019d160 ether <nil> up 0 0 0} veth} [10.88.0.3/16 eth0 fe80::e436:b6ff:
fe18:d7d1/64] [{Ifindex: 3 Dst: <nil> Src: <nil> Gw: 10.88.0.1 Flags: [] Table: 254} {Ifindex: 3 Dst: 10.88.0.0/16 Src: 10.88.0.3 Gw: <nil> Flags: [] Table: 254} {Ifindex: 3 Dst: fe80::/64 Src: <nil> Gw: <nil> F
lags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=9552 source=virtcontainers
Apr 10 19:01:34 openshift-test kata-runtime[9552]: time="2018-04-10T19:01:34.899703319Z" level=info msg="Virtual endpoint unmarshalled [{{308bcf59-a117-4bf5-b6c0-820e49367f76 br0 {eth0 02:00:ca:fe:00:00 [10.88.0
.3/16 eth0]} {tap0 e6:36:b6:18:d7:d1 []} 2 [0xc4201b82a0 0xc4201b82a8 0xc4201b82b0 0xc4201b82b8 0xc4201b82c0 0xc4201b82c8 0xc4201b82d0 0xc4201b82d8] [0xc4201b82e0 0xc4201b82e8 0xc4201b82f0 0xc4201b82f8 0xc4201b8
300 0xc4201b8308 0xc4201b8310 0xc4201b8318]} {{{3 1500 0 eth0 e6:36:b6:18:d7:d1 up|broadcast|multicast 69699 5 0 <nil>  0xc420228540 0 0xc42019dca0 ether <nil> up 0 0 0} veth} [10.88.0.3/16 eth0 fe80::e436:b6ff:
fe18:d7d1/64] [{Ifindex: 3 Dst: <nil> Src: <nil> Gw: 10.88.0.1 Flags: [] Table: 254} {Ifindex: 3 Dst: 10.88.0.0/16 Src: 10.88.0.3 Gw: <nil> Flags: [] Table: 254} {Ifindex: 3 Dst: fe80::/64 Src: <nil> Gw: <nil> F
lags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=9552 source=virtcontainers
Apr 10 19:01:34 openshift-test kata-runtime[9552]: time="2018-04-10T19:01:34.900059421Z" level=info msg="Container already stopped" arch=amd64 container-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47
d13c8246a name=kata-runtime pid=9552 pod-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a source=virtcontainers subsystem=container
Apr 10 19:01:39 openshift-test kata-runtime[9552]: time="2018-04-10T19:01:39.900358807Z" level=error msg="context deadline exceeded" command=delete name=kata-runtime pid=9552 source=runtime

Kata Proxy Log:

Apr 10 18:59:46 openshift-test kata-proxy[5456]: time="2018-04-10T18:59:46.921075516Z" level=info msg="[  750.699448] systemd-journald[68]: Sent WATCHDOG=1 notification.\n" name=kata-proxy pid=5456 source=agent
Apr 10 18:59:46 openshift-test kata-proxy[5456]: time="2018-04-10T18:59:46.921765919Z" level=info msg="time=\"2018-04-10T18:59:46.891697001Z\" level=debug msg=\"process exited\" name=kata-agent pid=183 source=ag
ent status=2\n" name=kata-proxy pid=5456 source=agent
Apr 10 18:59:47 openshift-test kata-proxy[5456]: time="2018-04-10T18:59:47.025085476Z" level=info msg="[  750.803835] XFS (sdb): Unmounting Filesystem\n" name=kata-proxy pid=5456 source=agent
Apr 10 18:59:47 openshift-test kata-proxy[5456]: time="2018-04-10T18:59:47.210463617Z" level=info msg="[  750.988926] sd 0:0:0:1: [sdb] Synchronizing SCSI cache\n" name=kata-proxy pid=5456 source=agent
Apr 10 18:59:47 openshift-test kata-proxy[5456]: time="2018-04-10T18:59:47.212457424Z" level=info msg="[  750.990979] sd 0:0:0:1: [sdb] Synchronize Cache(10) failed: Result: hostbyte=0x00 driverbyte=0x08\n" name
=kata-proxy pid=5456 source=agent
Apr 10 18:59:47 openshift-test kata-proxy[5456]: time="2018-04-10T18:59:47.213100227Z" level=info msg="[  750.991714] sd 0:0:0:1: [sdb] Sense Key : 0x5 [current] \n" name=kata-proxy pid=5456 source=agent
Apr 10 18:59:47 openshift-test kata-proxy[5456]: time="2018-04-10T18:59:47.213749629Z" level=info msg="[  750.992390] sd 0:0:0:1: [sdb] ASC=0x25 ASCQ=0x0 \n" name=kata-proxy pid=5456 source=agent
Apr 10 18:59:47 openshift-test kata-proxy[5456]: time="2018-04-10T18:59:47.436432299Z" level=info msg="time=\"2018-04-10T18:59:47.413437003Z\" level=debug msg=\"process exited\" name=kata-agent pid=143 source=ag
ent status=2\n" name=kata-proxy pid=5456 source=agent
Apr 10 18:59:47 openshift-test kata-proxy[5456]: time="2018-04-10T18:59:47.446896735Z" level=info msg="[  751.225724] XFS (sda): Unmounting Filesystem\n" name=kata-proxy pid=5456 source=agent
Apr 10 18:59:48 openshift-test kata-proxy[5456]: time="2018-04-10T18:59:48.018391112Z" level=info msg="[  751.797095] sd 0:0:0:0: [sda] Synchronizing SCSI cache\n" name=kata-proxy pid=5456 source=agent
Apr 10 18:59:48 openshift-test kata-proxy[5456]: time="2018-04-10T18:59:48.020328919Z" level=info msg="[  751.798841] sd 0:0:0:0: [sda] Synchronize Cache(10) failed: Result: hostbyte=0x04 driverbyte=0x00\n" name
=kata-proxy pid=5456 source=agent

Kata Shim Log:

Apr 10 18:47:18 openshift-test kata-shim[5481]: time="2018-04-10T18:47:18.222300509Z" level=info container=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a exec-id=58b5cb85d95895239edc9fd0d0ba67c
9bad5c28e6271090f227dc47d13c8246a name=kata-shim pid=1 source=shim version=0.0.1-2bdea2e41109b6b71c600899e1bf5794b125200d
Apr 10 18:47:18 openshift-test kata-shim[5481]: time="2018-04-10T18:47:18.235241537Z" level=info msg="Error getting window size" container=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a error="
inappropriate ioctl for device" exec-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a fd=0 name=kata-shim pid=1 source=shim
Apr 10 18:47:23 openshift-test kata-shim[5611]: time="2018-04-10T18:47:23.619074256Z" level=info container=dca6febc05d996125ea87bac34aa86241a652e6d4ad82632d59a23148f12eae9 exec-id=dca6febc05d996125ea87bac34aa862
41a652e6d4ad82632d59a23148f12eae9 name=kata-shim pid=1 source=shim version=0.0.1-2bdea2e41109b6b71c600899e1bf5794b125200d
Apr 10 18:47:23 openshift-test kata-shim[5611]: time="2018-04-10T18:47:23.619730057Z" level=info msg="Error getting window size" container=dca6febc05d996125ea87bac34aa86241a652e6d4ad82632d59a23148f12eae9 error="
inappropriate ioctl for device" exec-id=dca6febc05d996125ea87bac34aa86241a652e6d4ad82632d59a23148f12eae9 fd=0 name=kata-shim pid=1 source=shim
Apr 10 18:59:46 openshift-test kata-shim[5611]: time="2018-04-10T18:59:46.924504728Z" level=info msg="using shim to proxy exit code" container=dca6febc05d996125ea87bac34aa86241a652e6d4ad82632d59a23148f12eae9 exe
c-id=dca6febc05d996125ea87bac34aa86241a652e6d4ad82632d59a23148f12eae9 exitcode=2 name=kata-shim pid=1 source=shim
Apr 10 18:59:47 openshift-test kata-shim[5481]: time="2018-04-10T18:59:47.437922404Z" level=info msg="using shim to proxy exit code" container=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a exe
c-id=58b5cb85d95895239edc9fd0d0ba67c9bad5c28e6271090f227dc47d13c8246a exitcode=2 name=kata-shim pid=1 source=shim

CRI-O version: 1.9
Openshift version: 3.7.1
Latest Kata containers.

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions