pungi

#1799 Pungi doesn't always exit on DOOMED
Closed: Fixed by lsedlar. Opened by adamwill.

Closed: Fixed
Reopen Issue

When a non-failable image fails, Pungi is supposed to write a log message, update the compose status to DOOMED, and exit. The code for this is here. It all looks very straightforward - log the error, update the status file, flush stdout and stderr, and sys.exit(1). What could possibly go wrong?

Well...somehow it does. We've frequently, recently, seen cases where a compose was DOOMED, but pungi-koji kept running. This is a problem because it prevents any further composes from running (we use a lock wrapper thingy to ensure there's only ever one compose running at a time).

Here's the ending of the log from such a case (Fedora-Rawhide-20241121.n.0):

2024-11-21 07:08:22 [ERROR   ] Compose run failed: ImageBuild task failed: 126077562. See /mnt/koji/compose/rawhide/Fedora-Rawhide-20241121.n.0/logs/aarch64/imagebuild-Spins-KDE-raw-xz.aarch64.log for more details.
2024-11-21 07:08:22 [ERROR   ] Extended traceback in: /mnt/koji/compose/rawhide/Fedora-Rawhide-20241121.n.0/logs/global/traceback.global.log
2024-11-21 07:08:22 [CRITICAL] Compose failed: /mnt/koji/compose/rawhide/Fedora-Rawhide-20241121.n.0
2024-11-21 07:08:22 [INFO    ] Failed image-build on variant <Labs>, arch <*>, subvariant <Python_Classroom>.
2024-11-21 07:08:22 [INFO    ] Failed image-build on variant <Labs>, arch <*>, subvariant <Scientific>.
2024-11-21 07:08:22 [INFO    ] Failed image-build on variant <Server>, arch <*>, subvariant <Server>.
2024-11-21 07:08:22 [INFO    ] Failed image-build on variant <Labs>, arch <*>, subvariant <Python_Classroom>.
2024-11-21 07:08:22 [INFO    ] Failed image-build on variant <Spins>, arch <*>, subvariant <SoaS>.
2024-11-21 07:08:22 [INFO    ] Failed image-build on variant <Spins>, arch <*>, subvariant <Xfce>.
2024-11-21 07:08:22 [INFO    ] Failed image-build on variant <Spins>, arch <*>, subvariant <LXQt>.
2024-11-21 07:08:22 [INFO    ] Failed live-media on variant <Labs>, arch <*>, subvariant <Design_suite>.
2024-11-21 07:08:22 [INFO    ] Failed live-media on variant <Spins>, arch <aarch64>, subvariant <i3>.
2024-11-21 07:08:22 [INFO    ] Failed live-media on variant <Spins>, arch <aarch64>, subvariant <LXQt>.
2024-11-21 07:08:22 [INFO    ] Failed live-media on variant <Spins>, arch <aarch64>, subvariant <KDE>.
2024-11-21 07:08:22 [INFO    ] Failed live-media on variant <Workstation>, arch <aarch64>, subvariant <Workstation>.
2024-11-21 07:08:22 [DEBUG   ] Notification: '/usr/bin/pungi-fedmsg-notification' 'status-change', {'status': 'DOOMED', 'compose_id': 'Fedora-Rawhide-20241121.n.0', 'location': 'https://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20241121.n.0/compose', 'compose_date': '20241121', 'compose_type': 'nightly', 'compose_respin': 0, 'compose_label': None, 'compose_path': '/mnt/koji/compose/rawhide/Fedora-Rawhide-20241121.n.0', 'release_short': 'Fedora', 'release_name': 'Fedora', 'release_version': 'Rawhide', 'release_type': 'ga', 'release_is_layered': False}
2024-11-21 07:08:23 [DEBUG   ] Notification: 'pungi-wait-for-signed-ostree-handler' 'status-change', {'status': 'DOOMED', 'compose_id': 'Fedora-Rawhide-20241121.n.0', 'location': 'https://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20241121.n.0/compose', 'compose_date': '20241121', 'compose_type': 'nightly', 'compose_respin': 0, 'compose_label': None, 'compose_path': '/mnt/koji/compose/rawhide/Fedora-Rawhide-20241121.n.0', 'release_short': 'Fedora', 'release_name': 'Fedora', 'release_version': 'Rawhide', 'release_type': 'ga', 'release_is_layered': False}
2024-11-21 07:11:37 [OSTREE_INSTALLER] [INFO    ] [DONE ] Ostree phase for variant Silverblue, arch x86_64
2024-11-21 07:14:37 [OSTREE_INSTALLER] [INFO    ] [DONE ] Ostree phase for variant Kinoite, arch x86_64
2024-11-21 07:14:53 [OSTREE_INSTALLER] [INFO    ] [DONE ] Ostree phase for variant Kinoite, arch ppc64le
2024-11-21 07:17:56 [OSTREE_INSTALLER] [INFO    ] [DONE ] Ostree phase for variant Silverblue, arch ppc64le
2024-11-21 07:17:56 [INFO    ] [DONE ] ---------- PHASE: OSTREE_INSTALLER ----------
2024-11-21 07:17:56 [INFO    ] PHASE OSTREE_INSTALLER took 2551 seconds
2024-11-21 07:17:56 [DEBUG   ] Notification: '/usr/bin/pungi-fedmsg-notification' 'phase-stop', {'phase_name': 'ostree_installer', 'compose_id': 'Fedora-Rawhide-20241121.n.0', 'location': 'https://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20241121.n.0/compose', 'compose_date': '20241121', 'compose_type': 'nightly', 'compose_respin': 0, 'compose_label': None, 'compose_path': '/mnt/koji/compose/rawhide/Fedora-Rawhide-20241121.n.0', 'release_short': 'Fedora', 'release_name': 'Fedora', 'release_version': 'Rawhide', 'release_type': 'ga', 'release_is_layered': False}
2024-11-21 07:17:57 [DEBUG   ] Notification: 'pungi-wait-for-signed-ostree-handler' 'phase-stop', {'phase_name': 'ostree_installer', 'compose_id': 'Fedora-Rawhide-20241121.n.0', 'location': 'https://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20241121.n.0/compose', 'compose_date': '20241121', 'compose_type': 'nightly', 'compose_respin': 0, 'compose_label': None, 'compose_path': '/mnt/koji/compose/rawhide/Fedora-Rawhide-20241121.n.0', 'release_short': 'Fedora', 'release_name': 'Fedora', 'release_version': 'Rawhide', 'release_type': 'ga', 'release_is_layered': False}
2024-11-21 07:17:57 [INFO    ] [DONE ] Running pipeline (1/2). Phases: ostree, ostree_installer

Note we have:

2024-11-21 07:08:22 [CRITICAL] Compose failed: /mnt/koji/compose/rawhide/Fedora-Rawhide-20241121.n.0

which is the "Compose failed:" log message from the shutdown code path. We really should exit very soon after that gets logged. But no, we got messages up till nine and a half minutes later. And the process was still running till I killed it about half an hour ago, around 20:00.

What I suspect is happening is thread stuff. Yay threads. The weaver stuff uses threads, and at the time of this failure, some are still running. I'm guessing that just calling sys.exit() from the main thread isn't always enough to immediately tear down the subthreads and let us exit; it probably blocks waiting for the running subthreads to complete, or something. There's a note in a kobo.threads docstring which implies this - "It is essential to call this method. If you do any work in between start and stop, make sure the stop method will always be called, otherwise the program will never exit." And note that the last message logged is definitely to do with weaver thread stuff - "[DONE ] Running pipeline (1/2). Phases: ostree, ostree_installer", that message is logged in pungi.phases.weaver.PipelineThread.process() when the thread finishes. Note the thread that finished is thread 1/2, there's no trace of the second thread anywhere in the logs...

I suspect that on this path we need to be able to find the weaver thread pools and call kill on them before we sys.exit.

hum, maybe we should be calling try_kill_children and try_kill_koji_tasks on this "compose failure" path? We call them in sigterm_handler, but not on this path...

I think the weaver phase is innocent in this. I can reliably replicate the hang with a compose with no images by adding an unhandled exception to gather phase.

When the ostree phases were reordered, the start and stop are rather far apart, and any exception between them (i.e. in any of image building) will cause the stop to never happen, and the compose hangs (even if there is nothing for ostree to do as in my small test compose).

I tried playing around will killing all threads in case of failure, but it seems to be a bit of a footgun. The logger is shared between all threads, and it seems to be using some lock internally. Killing the thread was causing futher errors.

ah, so it's my fault? hmm. :D

What do you think of https://pagure.io/pungi/pull-request/1803 to fix it?

It's my fault for not noticing it in review :wine_glass:

Commit 8558b74d fixes this issue

oh, nice fix. thanks. I guess I'll close my PR.

This issue has been migrated to Fedora Forge:
https://forge.fedoraproject.org/pungi/pungi/issues/1799

Please continue any further discussion there.
Metadata
None
None
None
None
None
Related Pull Requests
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.