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

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

Closed
chavafg opened this issue Apr 10, 2018 · 8 comments
Closed

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

chavafg opened this issue Apr 10, 2018 · 8 comments
Assignees
@sboeuf

Comments

@chavafg
Copy link
Contributor

chavafg commented 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.
@chavafg chavafg mentioned this issue Apr 13, 2018
Merged
@sboeuf
Copy link

sboeuf commented Apr 13, 2018

@chavafg any chance you've been able to reproduce it with lower level API (crictl) ?

@chavafg
Copy link
Contributor Author

chavafg commented Apr 16, 2018

Not really, I see that on kata-runtime logs the call made is kata-runtime delete --force, so I tried to reproduce it using kata-runtime cli, but I couldn't see the error. Checking at crictl, they do not provide a --force option, so I tried removing containers and pods using crictl rm and crictl rms, but again the error didn't appear. Only way I could reproduce it is using the openshift cli.
Any idea of what else can I try?

And btw, this is also reproducible on kubernetes, using kubectl delete pod.

@sboeuf
Copy link

sboeuf commented Apr 16, 2018

Can you list the calls (maybe 10) to kata-runtime happening before this failure ?

@chavafg
Copy link
Contributor Author

chavafg commented Apr 16, 2018

These are the kata-runtime calls made from the pod creation.

Apr 16 14:58:03 openshift-artful kata-runtime[52547]: time="2018-04-16T14:58:03.767283654Z" level=info arguments="\"create --bundle /var/run/containers/storage/devicemapper-containers/05e3cc70dd6a7ff4f56dfedc272848f258481c4f688057a07ce398bd0e0e6371/userdata --pid-file /var/run/containers/storage/devicemapper-containers/05e3cc70dd6a7ff4f56dfedc272848f258481c4f688057a07ce398bd0e0e6371/userdata/pidfile 05e3cc70dd6a7ff4f56dfedc272848f258481c4f688057a07ce398bd0e0e6371\"" command=create commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=52547 source=runtime version=0.1.0
Apr 16 14:58:06 openshift-artful kata-runtime[52649]: time="2018-04-16T14:58:06.400721303Z" level=info arguments="\"start 05e3cc70dd6a7ff4f56dfedc272848f258481c4f688057a07ce398bd0e0e6371\"" command=start commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=52649 source=runtime version=0.1.0
Apr 16 14:58:06 openshift-artful kata-runtime[52666]: time="2018-04-16T14:58:06.419761684Z" level=info arguments="\"state 05e3cc70dd6a7ff4f56dfedc272848f258481c4f688057a07ce398bd0e0e6371\"" command=state commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=52666 source=runtime version=0.1.0
Apr 16 14:58:06 openshift-artful kata-runtime[52704]: time="2018-04-16T14:58:06.965673702Z" level=info arguments="\"create --bundle /var/run/containers/storage/devicemapper-containers/043c13149d43e45fc7fd84d8b43d6706211e5b309bc25ae03384d08db16a65a5/userdata --pid-file /var/run/containers/storage/devicemapper-containers/043c13149d43e45fc7fd84d8b43d6706211e5b309bc25ae03384d08db16a65a5/userdata/pidfile 043c13149d43e45fc7fd84d8b43d6706211e5b309bc25ae03384d08db16a65a5\"" command=create commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=52704 source=runtime version=0.1.0
Apr 16 14:58:07 openshift-artful kata-runtime[52729]: time="2018-04-16T14:58:07.134337918Z" level=info arguments="\"state 043c13149d43e45fc7fd84d8b43d6706211e5b309bc25ae03384d08db16a65a5\"" command=state commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=52729 source=runtime version=0.1.0
Apr 16 14:58:07 openshift-artful kata-runtime[52744]: time="2018-04-16T14:58:07.155580608Z" level=info arguments="\"start 043c13149d43e45fc7fd84d8b43d6706211e5b309bc25ae03384d08db16a65a5\"" command=start commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=52744 source=runtime version=0.1.0
Apr 16 14:58:07 openshift-artful kata-runtime[52752]: time="2018-04-16T14:58:07.169487667Z" level=info arguments="\"state 043c13149d43e45fc7fd84d8b43d6706211e5b309bc25ae03384d08db16a65a5\"" command=state commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=52752 source=runtime version=0.1.0
Apr 16 14:58:10 openshift-artful kata-runtime[52844]: time="2018-04-16T14:58:10.333149473Z" level=info arguments="\"list\"" command=list commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=52844 source=runtime version=0.1.0
Apr 16 14:58:11 openshift-artful kata-runtime[52929]: time="2018-04-16T14:58:11.009223633Z" level=info arguments="\"kill 043c13149d43e45fc7fd84d8b43d6706211e5b309bc25ae03384d08db16a65a5 TERM\"" command=kill commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=52929 source=runtime version=0.1.0
Apr 16 14:58:11 openshift-artful kata-runtime[52995]: time="2018-04-16T14:58:11.842441556Z" level=info arguments="\"state 043c13149d43e45fc7fd84d8b43d6706211e5b309bc25ae03384d08db16a65a5\"" command=state commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=52995 source=runtime version=0.1.0
Apr 16 14:58:11 openshift-artful kata-runtime[53001]: time="2018-04-16T14:58:11.853415002Z" level=info arguments="\"state 043c13149d43e45fc7fd84d8b43d6706211e5b309bc25ae03384d08db16a65a5\"" command=state commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=53001 source=runtime version=0.1.0
Apr 16 14:58:12 openshift-artful kata-runtime[53013]: time="2018-04-16T14:58:12.064937996Z" level=info arguments="\"state 043c13149d43e45fc7fd84d8b43d6706211e5b309bc25ae03384d08db16a65a5\"" command=state commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=53013 source=runtime version=0.1.0
Apr 16 14:58:12 openshift-artful kata-runtime[53019]: time="2018-04-16T14:58:12.079865759Z" level=info arguments="\"delete --force 043c13149d43e45fc7fd84d8b43d6706211e5b309bc25ae03384d08db16a65a5\"" command=delete commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=53019 source=runtime version=0.1.0
Apr 16 14:58:12 openshift-artful kata-runtime[53053]: time="2018-04-16T14:58:12.467656697Z" level=info arguments="\"kill 05e3cc70dd6a7ff4f56dfedc272848f258481c4f688057a07ce398bd0e0e6371 TERM\"" command=kill commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=53053 source=runtime version=0.1.0
Apr 16 14:58:13 openshift-artful kata-runtime[53106]: time="2018-04-16T14:58:13.27879359Z" level=info arguments="\"state 05e3cc70dd6a7ff4f56dfedc272848f258481c4f688057a07ce398bd0e0e6371\"" command=state commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=53106 source=runtime version=0.1.0
Apr 16 14:58:27 openshift-artful kata-runtime[53288]: time="2018-04-16T14:58:27.664395434Z" level=info arguments="\"delete --force 05e3cc70dd6a7ff4f56dfedc272848f258481c4f688057a07ce398bd0e0e6371\"" command=delete commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=53288 source=runtime version=0.1.0
Apr 16 14:59:32 openshift-artful kata-runtime[53628]: time="2018-04-16T14:59:32.68042868Z" level=info arguments="\"delete --force 05e3cc70dd6a7ff4f56dfedc272848f258481c4f688057a07ce398bd0e0e6371\"" command=delete commit=f74f61e8d1817a2775d5f8a70e4e2ad443e70821 name=kata-runtime pid=53628 source=runtime version=0.1.0

@sboeuf
Copy link

sboeuf commented Apr 16, 2018

Well first thing that strikes me here, the last 2 lines are trying to force delete the same containers. Maybe we are not handling this the way we should but obviously if only one call was made, we would not have any error here.

@grahamwhaley
Copy link
Contributor

hmm, 'double force delete' rings a bell in my head - something we have seen before somewhere that was out of our control - maybe it is a different issue though - @jodh-intel , do you remember if it is maybe relevant, and where we saw that before?

@sboeuf
Copy link

sboeuf commented Apr 16, 2018

@grahamwhaley nevermind, I have been talking with @chavafg and the failure happens on the first delete, the second is only a retry from openshift, which also fails obviously.

@sboeuf
Copy link

sboeuf commented Apr 16, 2018

I'll investigate a bit later today on this. I think this might be an issue related to the fact that we kill + delete --force while a kill + delete would work.

@chavafg chavafg mentioned this issue Apr 16, 2018
Open
sboeuf pushed a commit to sboeuf/runtime-1 that referenced this issue Apr 19, 2018
cli: Move the pod stop to OCI kill lifecycle
3dd3747 
This commit tries to address uses cases where the caller of the
runtime expects a kill to stop the container representing the pod,
meaning in our case the end of the VM.

This leads to some rework of the delete command since we want a
delete --force to always work, even if the container/pod has been
killed before.

Fixes kata-containers#197

Signed-off-by: Sebastien Boeuf <[email protected]>
@sboeuf sboeuf mentioned this issue Apr 19, 2018
Merged
@sboeuf sboeuf self-assigned this Apr 19, 2018
@sboeuf sboeuf added the review label Apr 19, 2018
sboeuf pushed a commit to sboeuf/runtime-1 that referenced this issue Apr 21, 2018
cli: Move the pod stop to OCI kill lifecycle
f492229 
This commit tries to address uses cases where the caller of the
runtime expects a kill to stop the container representing the pod,
meaning in our case the end of the VM.

This leads to some rework of the delete command since we want a
delete --force to always work, even if the container/pod has been
killed before.

Fixes kata-containers#197

Signed-off-by: Sebastien Boeuf <[email protected]>
@sboeuf sboeuf mentioned this issue Apr 23, 2018
Closed
@egernst egernst removed the review label Apr 26, 2018
zklei pushed a commit to zklei/runtime that referenced this issue Jun 13, 2019
@jodh-intel
Merge pull request kata-containers#197 from amshinde/correct-err-msg
ebc656f 
mount: Correct error message with mount failure.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@sboeuf sboeuf

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@grahamwhaley @chavafg @egernst @sboeuf