Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fail to start container, rootfs seems not ready. #1785

Closed
Random-Liu opened this issue Nov 20, 2017 · 56 comments · Fixed by #1868
Closed

Fail to start container, rootfs seems not ready. #1785

Random-Liu opened this issue Nov 20, 2017 · 56 comments · Fixed by #1868
Milestone

Comments

@Random-Liu
Copy link
Member

Random-Liu commented Nov 20, 2017

Our e2e test is still fairly flaky, many of them are caused by similar runc errors:

event for l7-default-backend-6d477bf555-rmtvn: {kubelet bootstrap-e2e-minion-group-c073} Failed: Error: failed to create containerd task: OCI runtime create failed: container_linux.go:296: starting container process caused "exec: \"/server\": stat /server: no such file or directory": unknown
event for monitoring-influxdb-grafana-v4-7649845859-cn67p: {kubelet bootstrap-e2e-minion-group-k0hs} Failed: Error: failed to create containerd task: OCI runtime create failed: container_linux.go:296: starting container process caused "exec: \"influxd\": executable file not found in $PATH": unknown
I1119 21:50:46.467] Nov 19 21:45:44.316: INFO: Logs of kube-system/monitoring-influxdb-grafana-v4-7649845859-x9nz2:grafana on node bootstrap-e2e-minion-group-s9k6
I1119 21:50:46.467] Nov 19 21:45:44.316: INFO:  : STARTLOG
I1119 21:50:46.467] standard_init_linux.go:195: exec user process caused "no such file or directory"
event for calico-typha-vertical-autoscaler-58f7d686f7-x4mj2: {kubelet bootstrap-e2e-minion-group-bcjl} Failed: Error: failed to create containerd container: open /tmp/ctd-username190490050/etc/passwd: no such file or directory
I1110 06:25:24.917] I1110 06:15:23.449592       1 nanny.go:94] Starting dnsmasq [-k --cache-size=1000 --no-negcache --log-facility=- --server=/cluster.local/127.0.0.1#10053 --server=/in-addr.arpa/127.0.0.1#10053 --server=/ip6.arpa/127.0.0.1#10053]
I1110 06:25:24.918] F1110 06:15:23.450086       1 nanny.go:181] Could not start dnsmasq with initial configuration: fork/exec /usr/sbin/dnsmasq: no such file or directory

It seems that rootfs is not complete. Do you know what could cause this? Have you ever seen this? Do you have any suggestion on how to debug this?
/cc @stevvooe @crosbymichael @dmcgowan

@Random-Liu
Copy link
Member Author

Random-Liu commented Nov 20, 2017

This doesn't always happen, and I did check some image, I believe those images should contain the missing files.

With this fixed, our e2e test should be much greener.

@crosbymichael
Copy link
Member

The exec error is coming from runc from exec'ing the process.

The other passwd error probably comes from parsing the passwd file to get the uid/gid.

Are these two separate errors or for the same container during a start?

@crosbymichael crosbymichael added this to the 1.0.0 milestone Nov 20, 2017
@Random-Liu
Copy link
Member Author

Random-Liu commented Nov 20, 2017

@crosbymichael Yeah, these are different failures in different test builds.

@Random-Liu
Copy link
Member Author

I've got more failures, such as:

event for pfpod: {kubelet bootstrap-e2e-minion-group-r31j} Failed: Error: failed to create containerd task: OCI runtime create failed: container_linux.go:296: starting container process caused "exec: \"/portforwardtester\": stat /portforwardtester: no such file or directory": unknown
event for rc-light-pjz9p: {kubelet bootstrap-e2e-minion-group-8gx3} Failed: Error: failed to create containerd task: OCI runtime create failed: container_linux.go:296: starting container process caused "exec: \"/consumer\": stat /consumer: no such file or directory": unknown

I'm not sure what is happening, will look into our code to make sure it's not a race on ourside. Although it's hard to imagine that this is a race on ourside, because we don't create the rootfs ourselves.

@crosbymichael
Copy link
Member

crosbymichael commented Nov 20, 2017

Are these new errors or existing? I mean, new from updating to the latest beta release?

@Random-Liu
Copy link
Member Author

Random-Liu commented Nov 20, 2017

I'm not 100% percent sure, because our e2e test flakes since the first day, we are trying to stabilize it, and it become better now.

I checked all our old builds, we updated containerd from 564600e to 1.0.0-beta.3 on Nov. 9th.
Before that we have 1.5 days test results, and I don't see the no such file failure.
Right after that, I start to see some failure:

I1110 05:05:07.483] Nov 10 05:04:53.136: INFO: At 2017-11-10 05:04:50 +0000 UTC - event for pod-ad503dff-c5d4-11e7-b8c4-0a580a3c19c9: {kubelet bootstrap-e2e-minion-group-dvs5} Failed: Error: failed to create containerd task: OCI runtime create failed: container_linux.go:296: starting container process caused "exec: \"/mounttest\": stat /mounttest: no such file or directory": unknown
I1110 10:30:38.918] Nov 10 10:29:10.631: INFO: At 2017-11-10 10:28:34 +0000 UTC - event for rc-light-rzl66: {kubelet bootstrap-e2e-minion-group-ngnp} Failed: Error: failed to create containerd task: OCI runtime create failed: container_linux.go:296: starting container process caused "exec: \"/consumer\": stat /consumer: no such file or directory": unknown
I1110 11:24:45.240] Nov 10 11:24:24.612: INFO: At 2017-11-10 11:24:12 +0000 UTC - event for e2e-net-client: {kubelet bootstrap-e2e-minion-group-7d5q} Failed: Error: failed to create containerd task: OCI runtime create failed: container_linux.go:296: starting container process caused "exec: \"/net\": stat /net: no such file or directory": unknown

Note that cri-containerd version is not changed across the failures above. It was just at the commit we update to containerd 1.0.0-beta.3.

@Random-Liu
Copy link
Member Author

I checked more builds, this really looks like a recent regression, after 564600e.

@crosbymichael
Copy link
Member

Thanks

@Random-Liu
Copy link
Member Author

Random-Liu commented Nov 20, 2017

564600e...v1.0.0-beta.3

The only thing looks related is the lease api change. However, I've no idea how that could cause this failure. Since our build is red since the first day, I can't 100% sure say this is a regression in v1.0.0-beta.3. However, I did check most builds before we switched to containerd 1.0.0-beta.3, and didn't see such failure. But I could easily find such failure after the upgrade.

Tell me if there is anything I could help to identify this, e.g. adding specific debug information, etc.

@dmcgowan
Copy link
Member

I did have one fix since then related to remapped snapshots #1732, a regression caused by leases. I would want to look at how the snapshot is being managed to make sure there is not another similar regression caused by it.

@Random-Liu
Copy link
Member Author

@dmcgowan Do you know how GC could cause this?

If a snapshot is GCed before rootfs is mounted, won't any error be returned?
If a snapshot is GCed after rootfs is mounted, what will happen?

@yanxuean
Copy link
Member

Maybe be this:
#1690 (comment)

@Random-Liu
Copy link
Member Author

@dmcgowan Do we have new findings on this?
This is still the main cause of our test flake. Is there anything I could do to help on this?

@yanxuean
Copy link
Member

There is a new bug. ref #1802
@Random-Liu @dmcgowan

@Random-Liu
Copy link
Member Author

I believe #1802 should be able to fix this.
I've updated containerd version in cri-containerd. Once I verify that the issue is fixed, I'll close this.

@Random-Liu
Copy link
Member Author

Still see this with #1802.
https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-cri-containerd-e2e-ubuntu-gce/477

I1127 23:35:45.472] Nov 27 23:30:37.282: INFO: At 2017-11-27 23:19:53 +0000 UTC - event for monitoring-influxdb-grafana-v4-554f5d97-5lsvj: {kubelet bootstrap-e2e-minion-group-7ttt} Failed: Error: failed to create containerd task: OCI runtime create failed: container_linux.go:296: starting container process caused "exec: \"/run.sh\": stat /run.sh: no such file or directory": unknown

@yanxuean
Copy link
Member

Maybe there are another problem yet. Today I will review it again.

@Random-Liu
Copy link
Member Author

Random-Liu commented Nov 30, 2017

Another occurrence
https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-cri-containerd-e2e-gci-gce/527

I1129 22:47:07.145] Nov 29 22:41:59.969: INFO: At 2017-11-29 22:31:03 +0000 UTC - event for l7-default-backend-57856c5f55-fs7zz: {kubelet bootstrap-e2e-minion-group-5qqx} Failed: Error: failed to create containerd task: OCI runtime create failed: container_linux.go:296: starting container process caused "exec: \"/server\": stat /server: no such file or directory": unknown

@Random-Liu
Copy link
Member Author

https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-cri-containerd-e2e-gci-gce/505

I1130 01:42:19.817] Nov 30 01:40:44.784: INFO: At 2017-11-30 01:35:48 +0000 UTC - event for pfpod: {kubelet bootstrap-e2e-minion-group-ds6g} Failed: Error: failed to create containerd task: OCI runtime create failed: container_linux.go:296: starting container process caused "exec: \"/portforwardtester\": stat /portforwardtester: no such file or directory": unknown

The fix seems not helping much. We still need to figure out this. :(

@Random-Liu
Copy link
Member Author

Random-Liu commented Nov 30, 2017

One weird thing is that it usually only happens to a fixed group of images, not all images.

@crosbymichael
Copy link
Member

@Random-Liu what images? I'm still unable to reproduce and have been running stress tests with 256 exec's per containers and I'm unable to reproduce

@Random-Liu
Copy link
Member Author

Random-Liu commented Nov 30, 2017

@crosbymichael Not just schema1 image.

$ ctr images ls | grep defaultbackend
gcr.io/google_containers/defaultbackend:1.3 application/vnd.docker.distribution.manifest.v2+json      sha256:fb91f9395ddf44df1ca3adf68b25dcbc269e5d08ba14a40de9abdedafacf93d4 1.3 MiB   linux/amd64

I'll debug it again today.

I'm still unable to reproduce and have been running stress tests with 256 exec's per containers and I'm unable to reproduce

It's not related to exec I think. Just sometimes, image/snapshot may be corrupted.

@crosbymichael
Copy link
Member

@Random-Liu if you can find a way to reproduce outside of the kube test CI that would help ;)

@Random-Liu
Copy link
Member Author

@Random-Liu
Copy link
Member Author

Random-Liu commented Dec 1, 2017

Another:
https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-cri-containerd-e2e-ubuntu-gce/547?log#log

event for calico-node-vertical-autoscaler-664dc78496-5p4mf: {kubelet bootstrap-e2e-minion-group-h1bn} Failed: Error: failed to create containerd container: open /tmp/ctd-username630229155/etc/passwd: no such file or directory

https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-cri-containerd-e2e-gci-gce/552?log#log

event for client-containers-6b6eafc0-d62a-11e7-84e5-0a580a3c7525: {kubelet bootstrap-e2e-minion-group-nqmv} Failed: Error: failed to create containerd task: OCI runtime create failed: container_linux.go:296: starting container process caused "exec: \"/ep-2\": stat /ep-2: no such file or directory": unknown

@Random-Liu
Copy link
Member Author

Random-Liu commented Dec 3, 2017

Debug PR: containerd/cri#463

cri-containerd.log: https://storage.googleapis.com/kubernetes-jenkins/logs/ci-cri-containerd-e2e-ubuntu-gce/620/artifacts/bootstrap-e2e-minion-group-s15x/cri-containerd.log
containerd.log: https://storage.googleapis.com/kubernetes-jenkins/logs/ci-cri-containerd-e2e-ubuntu-gce/620/artifacts/bootstrap-e2e-minion-group-s15x/containerd.log

The rootfs is empty since pulled/unpacked.

After pull/unpack, create a snapshot and check it:

I1203 19:36:25.968136    1915 instrumented_service.go:236] PullImage "gcr.io/kubernetes-e2e-test-images/test-webserver-amd64:1.0" with auth config &AuthConfig{Username:_token,Password:ya29.c.El4XBYBGsCqHT-CCcGduGzLP3lT_1Y7iXxux3qNbuTSTOg84elRqSF3jHiE48NhUzE14GsONWkZptN82Je3aKKxoNB8Eq-IKYvs7UCd776D-4OueGaeZbYvcxcEXkSkC,Auth:,ServerAddress:,IdentityToken:,RegistryToken:,}
I1203 19:36:26.295310    1915 image_pull.go:111] Unpack image "gcr.io/kubernetes-e2e-test-images/test-webserver-amd64:1.0"
I1203 19:36:26.563792    1915 image_pull.go:136] Pulled image "gcr.io/kubernetes-e2e-test-images/test-webserver-amd64:1.0" with image id "sha256:602b109cd5e7ac3675b09bc1a8787e9dc928d158c8e7e1801a9f85e126f520cc", repo tag "gcr.io/kubernetes-e2e-test-images/test-webserver-amd64:1.0", repo digest "gcr.io/kubernetes-e2e-test-images/test-webserver-amd64@sha256:cd237408ae94e22c4f5c6d7c6f56708341db6c428180fe1fe011c17bf9d03c50"
I1203 19:36:26.563824    1915 image_pull.go:156] Check image after pull image "sha256:602b109cd5e7ac3675b09bc1a8787e9dc928d158c8e7e1801a9f85e126f520cc"
I1203 19:36:26.563831    1915 remove_soon.go:90] Check image "sha256:602b109cd5e7ac3675b09bc1a8787e9dc928d158c8e7e1801a9f85e126f520cc" with entrypoint ""
I1203 19:36:26.572450    1915 remove_soon.go:41] Check snapshot "5ebe9e891706c8c0e40d1f0f8f2edd0aca0c6ab2163c5df3935d79804b15ea68" with entrypoint "/test-webserver"
I1203 19:36:26.576512    1915 events.go:62] Received container event timestamp - 2017-12-03 19:36:26.572340886 +0000 UTC, namespace - "k8s.io", topic - "/snapshot/prepare"
I1203 19:36:26.576611    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs058990367
E1203 19:36:26.596172    1915 image_pull.go:158] Failed to check image "sha256:602b109cd5e7ac3675b09bc1a8787e9dc928d158c8e7e1801a9f85e126f520cc": rootfs is empty
I1203 19:36:26.596187    1915 instrumented_service.go:241] PullImage "gcr.io/kubernetes-e2e-test-images/test-webserver-amd64:1.0" returns image reference "sha256:602b109cd5e7ac3675b09bc1a8787e9dc928d158c8e7e1801a9f85e126f520cc"

After WithNewSnapshot, check container snapshot directly:

I1203 19:36:26.621631    1915 remove_soon.go:126] Check snapshot "51dfa8bbc0ba31f2431305294f554563db1e4aead69dda2d957a40bdad6bd8b3" after snapshot creation
I1203 19:36:26.621649    1915 remove_soon.go:41] Check snapshot "51dfa8bbc0ba31f2431305294f554563db1e4aead69dda2d957a40bdad6bd8b3" with entrypoint "/test-webserver"
I1203 19:36:26.624747    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs894059689
E1203 19:36:26.641639    1915 remove_soon.go:128] Failed to check snapshot "51dfa8bbc0ba31f2431305294f554563db1e4aead69dda2d957a40bdad6bd8b3": rootfs is empty

Check container snapshot and image after start failure:

I1203 19:36:26.802443    1915 container_start.go:131] Check snapshot "51dfa8bbc0ba31f2431305294f554563db1e4aead69dda2d957a40bdad6bd8b3" after start failure
I1203 19:36:26.802562    1915 container_start.go:132] Check image "sha256:602b109cd5e7ac3675b09bc1a8787e9dc928d158c8e7e1801a9f85e126f520cc" after start failure
I1203 19:36:26.806140    1915 remove_soon.go:41] Check snapshot "51dfa8bbc0ba31f2431305294f554563db1e4aead69dda2d957a40bdad6bd8b3" with entrypoint "/test-webserver"
I1203 19:36:26.816701    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs245897030
I1203 19:36:26.816888    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs245897030/dev
I1203 19:36:26.817006    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs245897030/etc
I1203 19:36:26.817135    1915 remove_soon.go:171] -rwxr-xr-x         0/tmp/ctd-rootfs245897030/etc/hosts[""...]
I1203 19:36:26.817272    1915 remove_soon.go:171] -rwxr-xr-x         0/tmp/ctd-rootfs245897030/etc/resolv.conf[""...]
I1203 19:36:26.817368    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs245897030/proc
I1203 19:36:26.817469    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs245897030/sys
I1203 19:36:26.817603    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs245897030/var
I1203 19:36:26.817711    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs245897030/var/run
I1203 19:36:26.817809    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs245897030/var/run/secrets
I1203 19:36:26.817923    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs245897030/var/run/secrets/kubernetes.io
I1203 19:36:26.818029    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs245897030/var/run/secrets/kubernetes.io/serviceaccount
E1203 19:36:26.825625    1915 container_start.go:138] Failed to check snapshot "51dfa8bbc0ba31f2431305294f554563db1e4aead69dda2d957a40bdad6bd8b3": entrypoint "/test-webserver" not found
I1203 19:36:26.825806    1915 remove_soon.go:90] Check image "sha256:602b109cd5e7ac3675b09bc1a8787e9dc928d158c8e7e1801a9f85e126f520cc" with entrypoint "/test-webserver"
I1203 19:36:26.855960    1915 remove_soon.go:173] drwxr-xr-x      4096/tmp/ctd-rootfs348424685
E1203 19:36:26.893535    1915 container_start.go:141] Failed to check image "sha256:602b109cd5e7ac3675b09bc1a8787e9dc928d158c8e7e1801a9f85e126f520cc": rootfs is empty

It's not related to mount namespace. The image rootfs is empty since pull/unpack. And IIRC, once this happens, the image will become completely unusable. All following snapshot created will be constantly empty.

@dmcgowan @yanxuean Does the lease here actually work? https://github.com/kubernetes-incubator/cri-containerd/blob/master/vendor/github.com/containerd/containerd/image.go#L91-L95
It should, but I just randomly guess it is not for some reason?

@yanxuean
Copy link
Member

yanxuean commented Dec 4, 2017

The image have only a layer.
In snapshot.Prepare and snapshot.Mounts we will read all its parent snapshot, so its parent snapshot should be exist.
I don't understand why rootfs is empty after pullImage and after NewContainer. but it is not empty after NewTask.

@yanxuean
Copy link
Member

yanxuean commented Dec 4, 2017

If the lease don't work, There is a window its parent snapshot maybe be GCed. Then Subsequent snapshot.Mounts will fail. So the lease should has worked.

@dmcgowan
Copy link
Member

dmcgowan commented Dec 4, 2017

I don't understand why rootfs is empty after pullImage and after NewContainer. but it is not empty after NewTask.

The files that are showing up later on are temporary files needed to run the container.

Does the lease here actually work?

I see nothing in the logs that would indicate that GC is removing the snapshot. The snapshot deletion is happening after the container has already been deleted. I don't know of anything else that would delete the directory. The fact that the rootfs is empty after unpack makes me think that the image was never unpacked correctly in the first place. I am going to look for some races in the differ apply method.

@dmcgowan
Copy link
Member

dmcgowan commented Dec 4, 2017

I think this could cause it if unmount failed, the remove all would get triggered on the data. https://github.com/containerd/containerd/blob/master/diff/walking/differ.go#L97

This should probably just be a remove dir and log the errors. @yanxuean wdyt?

@yanxuean
Copy link
Member

yanxuean commented Dec 4, 2017

@dmcgowan Yeah. I agree with you. we can log for unmount fail

@yanxuean
Copy link
Member

yanxuean commented Dec 4, 2017

I think we can print the mounts gotten from snapshotter.Mounts in checkSnapshot.
It will verify if the parent snapshot is exist.
and we also can list the dir in mount. It will verify if there are content unpacked by diff.

@yanxuean
Copy link
Member

yanxuean commented Dec 4, 2017

func (c *criContainerdService) checkSnapshot(ctx context.Context, snapshot, entrypoint string, env []string, mustDump bool) error {
	glog.V(0).Infof("Check snapshot %q with entrypoint %q", snapshot, entrypoint)
	snapshotter := c.client.SnapshotService(c.config.ContainerdConfig.Snapshotter)
	mounts, err := snapshotter.Mounts(ctx, snapshot)
	if err != nil {
		return err
	}
	root, err := ioutil.TempDir("", "ctd-rootfs")
	if err != nil {
		return err
	}
	defer os.RemoveAll(root) // nolint: errcheck

@crosbymichael
Copy link
Member

@dmcgowan Ya, i think that is it. I looked at the code for those spec functions and they are using the snapshot key of the container so if unmount does fail, the remove all will delete everything in the snapshot.

I thought about this but initially blew it off because I thought we were using a temp snapshot key and it was not the original snapshot for the container.

I'm going to work on a patch for unmount that handles EBUSY and retries we well as seeing if we can use a readonly view for these functions.

crosbymichael added a commit to crosbymichael/containerd that referenced this issue Dec 4, 2017
This is another WIP to fix containerd#1785.

Signed-off-by: Michael Crosby <crosbymichael@gmail.com>
@crosbymichael
Copy link
Member

Did you all add cadvisor support around the same time as the last containerd version bump on the CI?

@Random-Liu
Copy link
Member Author

Random-Liu commented Dec 4, 2017

I see nothing in the logs that would indicate that GC is removing the snapshot. The snapshot deletion is happening after the container has already been deleted. I don't know of anything else that would delete the directory. The fact that the rootfs is empty after unpack makes me think that the image was never unpacked correctly in the first place. I am going to look for some races in the differ apply method.

Looks likely. Hope this time we could fix it. :)

Did you all add cadvisor support around the same time as the last containerd version bump on the CI?

In current integration, Cadvisor doesn't monitor containerd rootfs. We still get rootfs stats from containerd. However, could containerd snapshot Usage block unmount?

@stevvooe
Copy link
Member

stevvooe commented Dec 5, 2017

Since we think this is fixed in the current master, I am going to move to the 1.0.1 milestone for confirmation.

@Random-Liu
Copy link
Member Author

I think this has been fixed. Doesn't see this failure any more.

@yanxuean
Copy link
Member

yanxuean commented Dec 5, 2017

@Random-Liu
It is not the end.
We don't know why the unmount is fail.
When we sync #1877, the PullImage will fail. In #1877 we output the error of unmount.

@crosbymichael
Copy link
Member

@yanxuean i think this bug can be closed. The specific errors in this issue are addressed.

I think remaining issues could be split between containerd and cri-containerd. After watching the tests on cri-containerd, they are still pretty flakey and those need resolved to get accurate results. It feels like there could be some races in the code in the usage. Our CI is very stable and its very rare for us not to have a legitimate failure. Our stress tests are also stable with accurate results so we should look at getting the cri-containerd tests stable and double checking races in that codebase as well.

@yanxuean
Copy link
Member

yanxuean commented Dec 5, 2017

@crosbymichael
make sense.:)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants