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

podman rm, with more than one arg: error removing container, unlinkat, EBUSY #10454

Closed
edsantiago opened this issue May 25, 2021 · 53 comments · Fixed by containers/storage#926
Closed
Labels
flakes Flakes from Continuous Integration locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. rootless

Comments

@edsantiago
Copy link
Member

It looks like the cause of our new unlinkat/EBUSY flake is podman rm with more than one argument:

$ while :;do ./bin/podman run --name foo alpine true;./bin/podman run --name bar alpine true;./bin/podman rm foo bar || break;done
....
Error: error removing container 6b1063e2084c626ce8c4c11b02ee9caa8848a4f625a256d02febaa54e448a0c4 root filesystem: 1 error occurred:
        * unlinkat /home/esm/.local/share/containers/storage/overlay/bb7a8f6f9ba33943c30956aca2e90533a6aca86546c48b513fc55407603f83a8/merged: device or resource busy

It can take one minute, but more typically it's about five.

master @ 78df4f6. Running rootless on f34.

@edsantiago edsantiago added flakes Flakes from Continuous Integration rootless labels May 25, 2021
@edsantiago
Copy link
Member Author

Got it to fail with --log-level=debug:

DEBU[0000] environment variable TMPDIR is already defined, skip the settings from containers.conf
INFO[0000] Setting parallel job count to 25
DEBU[0000] Starting parallel job on container 2e7fd598ead121a836c788756db812685e3daa9f2698dfc08c21bfca32ed9d9f
DEBU[0000] Starting parallel job on container b2097e1c0ef4716bf6dc0d0f0871511a78a2effa1ab6d2aa03754ef985fe8ae3
DEBU[0000] Removing container b2097e1c0ef4716bf6dc0d0f0871511a78a2effa1ab6d2aa03754ef985fe8ae3
DEBU[0000] Removing all exec sessions for container b2097e1c0ef4716bf6dc0d0f0871511a78a2effa1ab6d2aa03754ef985fe8ae3
DEBU[0000] Cleaning up container b2097e1c0ef4716bf6dc0d0f0871511a78a2effa1ab6d2aa03754ef985fe8ae3
DEBU[0000] Network is already cleaned up, skipping...
DEBU[0000] Container b2097e1c0ef4716bf6dc0d0f0871511a78a2effa1ab6d2aa03754ef985fe8ae3 storage is already unmounted, skipping...
DEBU[0000] Container b2097e1c0ef4716bf6dc0d0f0871511a78a2effa1ab6d2aa03754ef985fe8ae3 storage is already unmounted, skipping...
DEBU[0010] failed to delete container "b2097e1c0ef4716bf6dc0d0f0871511a78a2effa1ab6d2aa03754ef985fe8ae3": 1 error occurred:
        * unlinkat /home/esm/.local/share/containers/storage/overlay/d7c83d85fbae9140223161f715bd606cf051ac591ade4d6f6bb833b43313676f/merged: device or resource busy

DEBU[0010] Failed to remove container b2097e1c0ef4716bf6dc0d0f0871511a78a2effa1ab6d2aa03754ef985fe8ae3: error removing container b2097e1c0ef4716bf6dc0d0f0871511a78a2effa1ab6d2aa03754ef985fe8ae3 root filesystem: 1 error occurred:
        * unlinkat /home/esm/.local/share/containers/storage/overlay/d7c83d85fbae9140223161f715bd606cf051ac591ade4d6f6bb833b43313676f/merged: device or resource busy

DEBU[0010] Removing container 2e7fd598ead121a836c788756db812685e3daa9f2698dfc08c21bfca32ed9d9f
DEBU[0010] Removing all exec sessions for container 2e7fd598ead121a836c788756db812685e3daa9f2698dfc08c21bfca32ed9d9f
DEBU[0010] Cleaning up container 2e7fd598ead121a836c788756db812685e3daa9f2698dfc08c21bfca32ed9d9f
DEBU[0010] Network is already cleaned up, skipping...
DEBU[0010] Container 2e7fd598ead121a836c788756db812685e3daa9f2698dfc08c21bfca32ed9d9f storage is already unmounted, skipping...
DEBU[0010] Container 2e7fd598ead121a836c788756db812685e3daa9f2698dfc08c21bfca32ed9d9f storage is already unmounted, skipping...
2e7fd598ead121a836c788756db812685e3daa9f2698dfc08c21bfca32ed9d9f
Error: error removing container b2097e1c0ef4716bf6dc0d0f0871511a78a2effa1ab6d2aa03754ef985fe8ae3 root filesystem: 1 error occurred:
        * unlinkat /home/esm/.local/share/containers/storage/overlay/d7c83d85fbae9140223161f715bd606cf051ac591ade4d6f6bb833b43313676f/merged: device or resource busy

@rhatdan
Copy link
Member

rhatdan commented May 25, 2021

@mheon I believe this could happen if the c.state.State == define.ContainerStateStopped and you attempt to remove it. Should we wait in the condition? If we wait, will the status be able to change?

@mheon
Copy link
Member

mheon commented May 25, 2021

I don't think that's possible - the container is already locked, there's no potential for a race.

DEBU[0010] Container 2e7fd598ead121a836c788756db812685e3daa9f2698dfc08c21bfca32ed9d9f storage is already unmounted, skipping...

That right there is extremely suspicious. The container is marked as unmounted in the DB, yet clearly it's still mounted because it's failing. I'm not sure how this happens - maybe the cleanup process already fired and failed to unmount?

@rhatdan
Copy link
Member

rhatdan commented May 25, 2021

@edsantiago could you attempt to remove the container afterwards to prove this is a race.

I was thinking the container could be stopped but not cleaned up yet, and we go in and attempt to remove it.

@edsantiago
Copy link
Member Author

I'm not sure what you mean by "remove the container afterwards" -- in all cases, both containers are gone: the rm is successful, at least as far as I can tell. podman ps -a always shows empty. Is that what you're asking?

@mheon
Copy link
Member

mheon commented May 25, 2021

@rhatdan We clean up as part of removal - you can see it in the logs.

The container is guaranteed to be gone after podman rm runs - if we're leaving anything behind, it's a storage container.

@rhatdan
Copy link
Member

rhatdan commented May 25, 2021

So we don't know if there is any storage container left? If there is a failure on removing from storage, should we remove from the database?

@rhatdan
Copy link
Member

rhatdan commented May 25, 2021

The only reason that the image would be busy, would be if something is mounted on the image or if a process is running on the image.

@mheon
Copy link
Member

mheon commented May 25, 2021

@rhatdan It's much better to get rid of the containers, even if there's a storage container left over - we had so many issues in the early days with containers that could not be removed at all without manual intervention. Defaulting to getting rid of the container is much safer.

@rhatdan
Copy link
Member

rhatdan commented May 25, 2021

Ok but any thoughts on what is happening?

@mheon
Copy link
Member

mheon commented May 25, 2021

Initial thought: cleanup process has already fired but failed to clean up, and the container was marked as unmounted despite this failure. As to why: lingering container process using the mountpoint, maybe? We really need to get the initial error message on the unmount attempt. Does this replicate outside of CI?

@edsantiago
Copy link
Member Author

Does this replicate outside of CI?

Trivially. See initial comment for one-line reproducer.

@rhatdan
Copy link
Member

rhatdan commented May 25, 2021

@edsantiago 10452 is always this flake. I think the problem can happen with a normal race.

@edsantiago
Copy link
Member Author

New information: there is a ten-second pause when this happens:

$ while :;do ./bin/podman run --name foo -d alpine true;./bin/podman run --name bar -d alpine true;./bin/podman run --name fubar -d alpine true;./bin/podman rm foo bar fubar || break;done | ts
....
May 25 09:30:55 2928a791accaadf6d5555a329220bd5522db587e9ad89a4a18e456438f3d48e6
May 25 09:30:55 15341f6fea9dfca020df227ebb4a8e9a2a7d1c008c69a207dcbe68491a49bb39
May 25 09:30:56 925501b27ffb98593115c1d75e5be70cbff091b7780a9e53e32d1aa5ef779258
May 25 09:30:56 2928a791accaadf6d5555a329220bd5522db587e9ad89a4a18e456438f3d48e6
May 25 09:30:56 15341f6fea9dfca020df227ebb4a8e9a2a7d1c008c69a207dcbe68491a49bb39
May 25 09:30:56 67bcf3f0e0fe0d87d39b449b8c8ceee02edfcf39933f48cd000486d1052bf063
May 25 09:30:57 ebb7c59a425b8facedf789c598ad0661e6ccf77d80ea25e940a7c7efcc6cd339
May 25 09:30:57 b6ed86f90f3508656641049d005e1a0e6ccdfaebfbf1ff17315e308c053879c5
Error: error removing container ebb7c59a425b8facedf789c598ad0661e6ccf77d80ea25e940a7c7efcc6cd339 root filesystem: 1 error occurred:
        * unlinkat /home/esm/.local/share/containers/storage/overlay/0fb14d50003fcbd3457f3afe4ea185d4d26af544cb70bee28bf3ad317976026c/merged: device or resource busy


May 25 09:31:08 67bcf3f0e0fe0d87d39b449b8c8ceee02edfcf39933f48cd000486d1052bf063
May 25 09:31:08 b6ed86f90f3508656641049d005e1a0e6ccdfaebfbf1ff17315e308c053879c5

@edsantiago
Copy link
Member Author

Here's my latest reproducer, slightly updated to make output more readable:

$ while :;do echo;./bin/podman run --name foo -d alpine true;./bin/podman run --name bar -d alpine true;./bin/podman run --name fubar -d alpine true;./bin/podman rm foo bar fubar || break;done | ts
...
May 25 09:32:54
May 25 09:32:54 32e042fab9276c040c9ef69a1bed91955e6716b9f8cab0930d17b398d1059e23
May 25 09:32:55 d588d4d67feabac480202da381fb5610437941fdcf1a1631524661d8bef214d2
May 25 09:32:55 d4083e76ed34d419f4604669ced0ebeda6af5446eea751b7497dc10920e1486f
May 25 09:32:56 d4083e76ed34d419f4604669ced0ebeda6af5446eea751b7497dc10920e1486f
May 25 09:32:56 32e042fab9276c040c9ef69a1bed91955e6716b9f8cab0930d17b398d1059e23
May 25 09:32:56 d588d4d67feabac480202da381fb5610437941fdcf1a1631524661d8bef214d2
May 25 09:32:56
May 25 09:32:56 b79a385ab25dfd5ba8687d39273013ab7c25f9a33a6174bdd38bad4b156f0056
May 25 09:32:57 9ab95a14ed09e07ebfa9ede24fb3b7479a2380dd58e3455316f5765f59d8ee19
May 25 09:32:57 4982b2c0bc7f6bc4313663d56337c6854638651b4b754fe6fb75a7d30ae75d4f
Error: error removing container 9ab95a14ed09e07ebfa9ede24fb3b7479a2380dd58e3455316f5765f59d8ee19 root filesystem: 1 error occurred:
        * unlinkat /home/esm/.local/share/containers/storage/overlay/7d7b1833de538603870e84beed40c294dc1f1a101a1e3ae58bf852a84766889e/merged: device or resource busy


May 25 09:33:08 b79a385ab25dfd5ba8687d39273013ab7c25f9a33a6174bdd38bad4b156f0056
May 25 09:33:08 4982b2c0bc7f6bc4313663d56337c6854638651b4b754fe6fb75a7d30ae75d4f

@edsantiago
Copy link
Member Author

With podman-3.1.2-3.fc34 on my laptop, changing ./bin/podman rm ... to /usr/bin/podman rm ..., the reproducer still fails.

However: if I change all ./bin/podman to /usr/bin/podman (i.e. the podman runs) ... it runs fine for thirty minutes and is still happily going. The implication, at least in my simple reading, is that (a) the problem is new since 3.1.2 and (b) the problem is in podman run, not podman rm. Does that make sense to anyone?

@rhatdan
Copy link
Member

rhatdan commented May 25, 2021

I just tried

podman rm -a -f
for i in {1..100}; do podman run --name test$i alpine true; done
x=$(for i in {1..100}; do echo -n "test$i "; done)
podman rm $x

And I am not getting any errors.

@edsantiago
Copy link
Member Author

What is the value of "podman"? Are you using system podman, or ./bin/podman from your tree?

FWIW your reproducer triggers the failure on my system:

$ for i in {1..100}; do ./bin/podman run --name test$i alpine true; done
$ ./bin/podman rm $(seq --format="test%.0f" 1 100)
....
56205dd46c54060b7db86b4a0433bd21d8dc65bf32557be115b9ab9715e56291
Error: error removing container ea2bc91f5a4d45fa6cc555aabc4a303a1bb8058ef1d6e59ff9182db7ef83eda8 root filesystem: 1 error occurred:
        * unlinkat /home/esm/.local/share/containers/storage/overlay/095937d3ee050e905abc877a3b99daf4681bbceff3d659269e17e98631c5cbf5/merged: device or resource busy

I can also reproduce it if I use /usr/bin/podman for the rm. It even fails twice:

f452547ae8a7aaf3324a92c1e632c94a92ec2271162fc4c64c0436994dca38fc
error removing container 154b29386b2dd66791d2a7aebf55854947896f14c05dd716e2ff611e4424237b root filesystem: 1 error occurred:
        * unlinkat /home/esm/.local/share/containers/storage/overlay/986ef7ba9bec3718ef04f862271832889dbf54e1150bd64060da7a3a4a34f190/merged: device or resource busy


Error: error removing container dc01084c75c5a2442f55b554060eb535e926a47a56324707c739c4f105284028 root filesystem: 1 error occurred:
        * unlinkat /home/esm/.local/share/containers/storage/overlay/6831f220168b8ac49b4206b99585c4dbcc10a973303e316210933f9436ef3ed7/merged: device or resource busy

I cannot reproduce the flake if I use /usr/bin/podman (3.1.2) for the run commands. IOW, I still believe the flake is a new bug in podman run, or at least something different that it is doing.

@rhatdan
Copy link
Member

rhatdan commented May 25, 2021

Well I can not get this to fail, but I am not using fuse-overlayfs.
@giuseppe Any ideas.

We are only seeing this on Ubuntu machines in CI system, although @edsantiago and @mheon have gotten it to fail on Fedora. With the reproducer above.

@mheon Was the fuse-overlayfs failure repeatable?

Newer versions of podman are executing the overlay fs with new options? Could this be related?

@rhatdan
Copy link
Member

rhatdan commented May 25, 2021

Running
$ for i in {1..100}; do ./bin/podman run --name test$i alpine true; done
$ ./bin/podman rm $(seq --format="test%.0f" 1 100)
On my machine works perfectly, but I am not using fuse-overlayfs, native overlay since I have the newer kernel.

@edsantiago
Copy link
Member Author

FYI my kernel is 5.11.17-300.fc34

I'm not feeling a great desire to git bisect right now, but if my hints above (10-second delay, problem in podman run not podman rm) don't help anyone, I will do so tomorrow.

@rhatdan
Copy link
Member

rhatdan commented May 25, 2021

I just forced fuse-overlay and it still does not fail for me.

$ for i in {1..100}; do ./bin/podman run --name test$i alpine true; done; ./bin/podman rm $(seq --format="test%.0f" 1 100)

@edsantiago
Copy link
Member Author

$ podman info|grep -1i fuse                                                                                                                           -
    overlay.mount_program:
      Executable: /usr/bin/fuse-overlayfs
      Package: fuse-overlayfs-1.5.0-1.fc34.x86_64
      Version: |-
        fusermount3 version: 3.10.3
        fuse-overlayfs: version 1.5
        FUSE library version 3.10.3
        using FUSE kernel interface version 7.31
  graphRoot: /home/esm/.local/share/containers/storage

@giuseppe
Copy link
Member

I think it could also be a regression in the kernel, I am still troubleshooting but after some time using the reproducer provided by @edsantiago I am able to reproduce locally.

It gets the system in a weird state:

$ podman unshare
$ grep fuse-overlayfs /proc/self/mountinfo 
2497 896 0:121 / /home/gscrivano/.local/share/containers/storage/overlay/07fc566c5d6611235bae328ec3a556a5efaf436cff9ac083e806ba72527f7210/merged rw,nodev,noatime - fuse.fuse-overlayfs fuse-overlayfs rw,user_id=0,group_id=0,default_permissions,allow_other
$ umount /home/gscrivano/.local/share/containers/storage/overlay/07fc566c5d6611235bae328ec3a556a5efaf436cff9ac083e806ba72527f7210/merged
umount: /home/gscrivano/.local/share/containers/storage/overlay/07fc566c5d6611235bae328ec3a556a5efaf436cff9ac083e806ba72527f7210/merged: not mounted.
$ fusermount3 -u /home/gscrivano/.local/share/containers/storage/overlay/07fc566c5d6611235bae328ec3a556a5efaf436cff9ac083e806ba72527f7210/merged
fusermount3: failed to unmount /home/gscrivano/.local/share/containers/storage/overlay/07fc566c5d6611235bae328ec3a556a5efaf436cff9ac083e806ba72527f7210/merged: Invalid argument

and strace says:

umount2("/home/gscrivano/.local/share/containers/storage/overlay/07fc566c5d6611235bae328ec3a556a5efaf436cff9ac083e806ba72527f7210/merged", 0) = -1 EINVAL (Invalid argument)

Interesting, if I join just the mount namespace as root on the host, I am able to umount it.

@edsantiago
Copy link
Member Author

could also be a regression in the kernel

It could be, but why can I not reproduce the problem with /usr/bin/podman (3.1.2)?

Incidentally, this is also happening with podman rm -a, not just explicitly-enumerated containers.

@rhatdan
Copy link
Member

rhatdan commented May 26, 2021

Yes I switched the test to run with three podman rm commands rather then one, and it still flaked. It is definitely something to do with rootless podman rm failing. because of a mount point in use.

Could this be some kind of mount space leak?

@edsantiago
Copy link
Member Author

sys: podman start --all - start all containers

Also failing in run-basic test, which does podman rm -a:

sys: podman run - basic tests

Hmmmm, this is not failing on fedora CI, only ubuntu CI, and both ubuntu 2010 and 2104. To me that argues a little against it being a kernel issue (but I'm no expert)

@edsantiago
Copy link
Member Author

$ podman unshare
# umount ~/.local/share/containers/storage/overlay
# mount|grep /home/esm/.local/share/containers/storage|awk '{print $3}'
[ lots and lots]
# mount|grep /home/esm/.local/share/containers/storage|awk '{print $3}'|xargs -l1 umount    ! succeeds

@edsantiago
Copy link
Member Author

I really wanted to be wrong, but I can't reproduce the flake with 62c14dc (the commit just prior to #10219).

@vrothberg
Copy link
Member

I really wanted to be wrong, but I can't reproduce the flake with 62c14dc (the commit just prior to #10219).

I like that more :^) I meditated over dinner on how #10219 may have caused it but turned in circles.

@edsantiago
Copy link
Member Author

I may not have been clear: my comment above indicates that #10219 is almost 100% guaranteed to be the culprit. I'm sorry.

@vrothberg
Copy link
Member

On nooos :^) I read can reproduce.

@vrothberg
Copy link
Member

@edsantiago can you reproduce after reverting commit 8352e5b?

@edsantiago
Copy link
Member Author

@vrothberg did you really want me to try to resolve the conflicts in git revert 8352e? That would take me the majority of the day, and I'm not confident I could get it right.

@vrothberg
Copy link
Member

@vrothberg did you really want me to try to resolve the conflicts in git revert 8352e? That would take me the majority of the day, and I'm not confident I could get it right.

No, absolutely not, sorry for not checking if it reverts cleanly. Can you try with https://paste.centos.org/view/a5a90a57?

@vrothberg
Copy link
Member

Too late to function properly. Need to massage the patch.

@vrothberg
Copy link
Member

That'll compile: https://paste.centos.org/view/a51c1483

@vrothberg
Copy link
Member

vrothberg commented May 26, 2021

The thing is that (libimage.Rutime*).Shutdown(...) executes the same code as before. The only thing that #10219 really added is a small delay before shutting down the store. But my eyes are tired and maybe I miss the obvious.

@edsantiago
Copy link
Member Author

Here's the attempt I came up with. It looks pretty similar to yours. I cannot (can not) reproduce the flake with that patch. Three iterations so far (with 10219, it almost always fails in one iteration). Sorry again.

@edsantiago
Copy link
Member Author

@containers/podman-maintainers may I humbly suggest that this is an all-hands-on-deck moment?

@mheon
Copy link
Member

mheon commented May 26, 2021

Most suspicious bit I can see is switching from shutting down the store directly, to calling the Libimage shutdown function. That would be the first thing I look at.

@vrothberg
Copy link
Member

@edsantiago, thanks a lot for testing!

One last request, could you test: https://paste.centos.org/view/fa6a32d4?

Here, we're not using libimage to shutdown the store. I do not yet know why that would make any difference but I cannot rule it out at that point.

@vrothberg
Copy link
Member

Most suspicious bit I can see is switching from shutting down the store directly, to calling the Libimage shutdown function. That would be the first thing I look at.

https://paste.centos.org/view/fa6a32d4 reverts that. But as mentioned above, libimage shutdown does exactly that as well. It's not obvious to me yet how that would impact.

Anyhow, I have to leave the keyboard. Good luck, folks!

@edsantiago
Copy link
Member Author

Four iterations so far with the above patch (fa6a32d4). No flakes. To be clear: r.libimageRuntime.Shutdown() seems to be the cause of the flake.

@edsantiago
Copy link
Member Author

Well.... I left the reproducer running anyway, and it just triggered. I don't know how many iterations, but according to the github timestamp above it took 26 minutes. This tells me that #10219 did not cause the problem, it just made it more pronounced.

@edsantiago
Copy link
Member Author

Another unhelpful data point: I reverted back to 62c14dc (commit before #10219), this time letting the reproducer run uninterrupted. Three hours later, no failures. Is it possible that the simple existence of libimageEventsShutdown is causing the problem? This code is too Go-idiomatic for my C-trained brain.

@vrothberg
Copy link
Member

Thanks a lot for all the data points, @edsantiago. I am under the impression that #10219 is merely increasing the chance of hitting the issue; maybe because it takes slightly longer to shutdown the store.

@edsantiago
Copy link
Member Author

I left 62c14dc running all night. 605 iterations, not a single crash.

@vrothberg
Copy link
Member

@giuseppe may have found the source in c/storage. Could be an issue in comparing time stamps.

giuseppe added a commit to giuseppe/storage that referenced this issue May 27, 2021
use s.graphLock.Modified() instead of s.graphLock.TouchedSince().

TouchedSince() seems to fail in some cases when comparing the inode
mtime with the current time.

Avoid such kind of problems in a critical code path as store.mount(),
as we must be sure there is already a driver home mount present,
otherwise it the next process may cover the container mount with the
home mount.

Closes: containers/podman#10454

Signed-off-by: Giuseppe Scrivano <[email protected]>
@giuseppe
Copy link
Member

opened a PR: containers/storage#926

rhatdan pushed a commit to rhatdan/storage that referenced this issue May 27, 2021
use s.graphLock.Modified() instead of s.graphLock.TouchedSince().

TouchedSince() seems to fail in some cases when comparing the inode
mtime with the current time.

Avoid such kind of problems in a critical code path as store.mount(),
as we must be sure there is already a driver home mount present,
otherwise it the next process may cover the container mount with the
home mount.

Closes: containers/podman#10454

Signed-off-by: Giuseppe Scrivano <[email protected]>
@github-actions github-actions bot added the locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. label Sep 21, 2023
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Sep 21, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
flakes Flakes from Continuous Integration locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. rootless
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants