add epbf program to trace podman cleanup errors in CI

[Luap99]

See commits, I just want to check if this even works. Hopefully this allows me to properly understand cleanup errors.

Does this PR introduce a user-facing change?

None

[openshift-ci]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: Luap99

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

• OWNERS [Luap99]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

[packit-as-a-service]

Cockpit tests failed for commit f241ed0. @martinpitt, @jelly, @mvollmer please check.

[Luap99]

In case anyone is interested here is an example log:
https://api.cirrus-ci.com/v1/artifact/task/6197821693493248/cleanup_tracer/podman-cleanup-tracer.log

It doesn't look nice mostly because the argv lines is printed with zero bytes not spaces, I don't have a way to get rid of that in my program but I guess I could pipe into sed to replace all zero bytes with spaces to make it easier to read.

[Luap99]

@edsantiago please pick this one as well for the no retry PR, maybe I can find the cause in this new log.

[edsantiago]

Here ya go f39 root. [EDIT: direct link to cleanup tracer log]. This is my second run; first one did not have any relevant flakes. This run had only one. I'll rerun at least once more today.

[edsantiago]

This one has two (debian root). It was the only failure in the third run. I've pushed one more time, but will not be checking its status again tonight.

[Luap99]

Ok that doesn't seems to include any new things AFAICS, it does confirm what I have been saying the cleanup is called twice. The only way I see this happening is what the cleanup process failed but in the logs exit codes I clearly see no errors or kill signals send. So there truly must be a condition in our code that is calling cleanup twice even if there was no error the first time...

[Luap99]

@edsantiago I assume the no flake retry is the only thing I need to trigger this?

I added the parent pid info to my log as it wasn't clear if netavark teardown was run by the some podman command or two different ones.

[edsantiago]

Not to trigger it, more precisely, to see it. I think the error is happening all the time, it's just that normally we have to examine each individual log to find it. Yes, setting retries to 0 should make failures visible.

[Luap99]

Not to trigger it, more precisely, to see it. I think the error is happening all the time, it's just that normally we have to examine each individual log to find it. Yes, setting retries to 0 should make failures visible.

Yes that is what I meant.

[Luap99]

Interesting I found the netns error also in my log for the cleanup process. So it can happen without us ever seeing as wel and without causing a test failure.

stderr 07:36:29.528707 79038    79009    podman      time="2024-08-07T07:36:29-05:00" level=error msg="Cleaning up container: failed to clean up container e22e54194869285aef9d593f0cdfff9e23d5fdfb14615dbcf71aac829d225a77: cannot get namespace path unless container edb052e52aac57efd13979ce3921481aff6baa06e556199775ab0ca6b567cdd8 is running: container is stopped"
stderr 07:36:29.528744 79038    79009    podman      Error: failed to clean up container e22e54194869285aef9d593f0cdfff9e23d5fdfb14615dbcf71aac829d225a77: cannot get namespace path unless container edb052e52aac57efd13979ce3921481aff6baa06e556199775ab0ca6b567cdd8 is running: container is stopped
ainerexec   07:36:29.529410 79114    79061    podman       /usr/libexec/podman/netavark --config /run/containers/networks --rootless=false --aardvark-binary=/usr/libexec/podman/aardvark-dns teardown /run/netns/netns-00a1fc0e-8ec3-0941-ba07-9f4989af1e46
cmd    07:36:29.529780 79114    79061    /usr/libexec/podman/netavark�--config�/run/containers/networks�--rootless=false�--aardvark-binary=/usr/libexec/podman/aardvark-dns�teardown�/run/netns/netns-00a1fc0e-8ec3-0941-ba07-9f4989af1e46�
exit   07:36:29.617636 79114    79061    netavark     0 0
stderr 07:36:29.638209 79038    79009    podman      time="2024-08-07T07:36:29-05:00" level=error msg="IPAM error: failed to get ips for container ID edb052e52aac57efd13979ce3921481aff6baa06e556199775ab0ca6b567cdd8 on network podman-default-kube-network"
ontainer edb052e52aac57efd13979ce3921481aff6baexec   07:36:29.638942 79150    79038    podman       /usr/libexec/podman/netavark --config /run/containers/networks --rootless=false --aardvark-binary=/usr/libexec/podman/aardvark-dns teardown /run/netns/netns-00a1fc0e-8ec3-0941-ba07-9f4989af1e46
cmd    07:36:29.639236 79150    79038    /usr/libexec/podman/netavark�--config�/run/containers/networks�--rootless=false�--aardvark-binary=/usr/libexec/podman/aardvark-dns�teardown�/run/netns/netns-00a1fc0e-8ec3-0941-ba07-9f4989af1e46�
exit   07:36:29.642237 79150    79038    netavark     1 0
stderr 07:36:29.642647 79038    79009    podman      time="2024-08-07T07:36:29-05:00" level=error msg="IPAM error: failed to find ip for subnet 10.89.0.0/24 on network podman-default-kube-network"
775ab0ca6b567cdd8 on network podman-defaulstderr 07:36:29.642714 79038    79009    podman      time="2024-08-07T07:36:29-05:00" level=error msg="netavark: open container netns: open /run/netns/netns-00a1fc0e-8ec3-0941-ba07-9f4989af1e46: IO error: No such file or directory (os error 2)"
-network"
ontainer edb052e52aac57efd13979ce3921481aff6bastderr 07:36:29.642747 79038    79009    podman      time="2024-08-07T07:36:29-05:00" level=error msg="Unable to clean up network for container edb052e52aac57efd13979ce3921481aff6baa06e556199775ab0ca6b567cdd8: \"unmounting network namespace for container edb052e52aac57efd13979ce3921481aff6baa06e556199775ab0ca6b567cdd8: failed to remove ns path: remove /run/netns/netns-00a1fc0e-8ec3-0941-ba07-9f4989af1e46: no such file or directory, failed to unmount NS: at /run/netns/netns-00a1fc0e-8ec3-0941-ba07-9f4989af1e46: no such file or directory\""
exit   07:36:29.656424 79103    78908    podman       0 0
exit   07:36:29.676194 79038    79009    podman       125 0

https://api.cirrus-ci.com/v1/artifact/task/5220866676490240/cleanup_tracer/podman-cleanup-tracer.log
https://api.cirrus-ci.com/v1/artifact/task/5220866676490240/html/int-podman-rawhide-root-host-sqlite.log.html

[packit-as-a-service]

Ephemeral COPR build failed. @containers/packit-build please check.

[Luap99]

@edsantiago Great news I am confident that I found the root cause, a locking/container state misuse bug that caused us to add the netns back after we cleaned it up already.
Please give d6bcc14 a try. Hopefully this is enough, I will prepare a proper PR with a better description on Monday.

[edsantiago]

One new failure seen, f39 root:

# podman [options] network ls --quiet
net5ef1e5e5df3c173e8948e8e487fc7c21c14438e290de0a5a04e3f8b610f60b47
networkIDTest
podman
podman-default-kube-network
time="2024-08-10T17:56:31Z" level=warning msg="Error reading network config file \"/etc/containers/networks/net25120a9e54ed259eaa0b8b853f1e8cda89d0c538a55825de0e591c2e67950554.json\": EOF"

[FAILED] Unexpected warnings seen on stderr: "time=\"2024-08-10T17:56:31Z\" level=warning msg=\"Error reading network config file \\\"/etc/containers/networks/net25120a9e54ed259eaa0b8b853f1e8cda89d0c538a55825de0e591c2e67950554.json\\\": EOF\""

Looks more like a race in network ls than anything you've changed, but still, it's a new one I don't remember seeing before.

[edsantiago]

It took a LOT of runs, but here's what looks like the same issue. rawhide rootless:

$ podman [options] stop --all -t 0
Error: removing container 78e1e7c4d390f06129b5a13de8ede2351eafaf3ccc76f665177b7e5ce3bc922c network: unmounting network namespace for container 78e1e7c4d390f06129b5a13de8ede2351eafaf3ccc76f665177b7e5ce3bc922c: failed to remove ns path: remove /run/user/2153/netns/netns-1fac2ba0-0d2a-10cb-7dbe-900b0f29ae60: device or resource busy

[Luap99]

It took a LOT of runs, but here's what looks like the same issue. rawhide rootless:

$ podman [options] stop --all -t 0
Error: removing container 78e1e7c4d390f06129b5a13de8ede2351eafaf3ccc76f665177b7e5ce3bc922c network: unmounting network namespace for container 78e1e7c4d390f06129b5a13de8ede2351eafaf3ccc76f665177b7e5ce3bc922c: failed to remove ns path: remove /run/user/2153/netns/netns-1fac2ba0-0d2a-10cb-7dbe-900b0f29ae60: device or resource busy

Note the same issue (EBUSY vs ENOENT), this should be fixed by containers/common#2112, vendor in #23519

[Luap99]

Also d6bcc14 is such a generic issue it would not surprise me if this fixes other weird stop flakes as well.