rhel-10 tests flakes failing at the end of installation with ERR anaconda:Exception ignored in atexit callback: <function shutdown at 0x7f81dbab1e40>""

[rvykydal]

First spotted 08-29-2024. 08-28-2024 does not have logs for a different issue. 08-27-2024 did not hit the problem. Hit ~ 6/1000 test runs in the last week's dailies.

kstest.log virt-install.log

00:48:32,670 INFO systemd-logind:Removed session 1.
00:48:32,715 NOTICE udisksd:udisks daemon version 2.10.90 exiting
00:48:32,716 ERR anaconda:Exception ignored in atexit callback: <function shutdown at 0x7f81dbab1e40>
00:48:32,716 ERR anaconda:Traceback (most recent call last):
00:48:32,716 ERR anaconda:  File "/usr/lib64/python3.12/logging/__init__.py", line 2273, in shutdown
00:48:32,751 INFO systemd:Received SIGRTMIN+20 from PID 27156 (plymouthd).
00:48:32,928 INFO systemd:Started plymouth-poweroff.service - Show Plymouth Power Off Screen.
00:48:32,948 NOTICE kernel:audit: type=1400 audit(1724892512.947:809): avc:  denied  { create } for  pid=2236 comm="systemd-udevd" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=netlink_kobject_uevent_socket permissive=1
00:48:33,045 ERR anaconda:    h.release()
00:48:33,045 ERR anaconda:  File "/usr/lib64/python3.12/logging/__init__.py", line 975, in release
00:48:33,045 ERR anaconda:    def release(self):
00:48:33,045 ERR anaconda:  File "/sbin/anaconda", line 305, in <lambda>
00:48:33,094 INFO systemd:lvm2-lvmdbusd.service: Deactivated successfully.
00:48:33,094 INFO systemd:Stopped lvm2-lvmdbusd.service - LVM2 D-Bus service.
00:48:33,138 ERR anaconda:    signal.signal(signal.SIGTERM, lambda num, frame: sys.exit(1))
00:48:33,140 ERR anaconda:                                                     ^^^^^^^^^^^
00:48:33,140 ERR anaconda:SystemExit: 1

virt-install.log

23:57:54,341 ERR anaconda:Exception ignored in atexit callback: <function shutdown at 0x7f87d5571e40>
23:57:54,341 ERR anaconda:Traceback (most recent call last):
23:57:54,341 ERR anaconda:  File "/usr/lib64/python3.12/logging/__init__.py", line 2263, in shutdown
23:57:54,414 INFO systemd:Started plymouth-poweroff.service - Show Plymouth Power Off Screen.

virt-install.log

23:54:06,439 INFO systemd-logind:Removed session 1.
23:54:06,462 NOTICE udisksd:udisks daemon version 2.10.90 exiting
23:54:06,463 INFO systemd:Received SIGRTMIN+20 from PID 28612 (plymouthd).
23:54:06,520 ERR anaconda:Exception ignored in atexit callback: <function shutdown at 0x7fb020251e40>
23:54:06,520 ERR anaconda:Traceback (most recent call last):
23:54:06,520 ERR anaconda:  File "/usr/lib64/python3.12/logging/__init__.py", line 2264, in shutdown
23:54:06,593 NOTICE kernel:audit: type=1400 audit(1724889246.591:957): avc:  denied  { create } for  pid=2235 comm="systemd-udevd" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=netlink_kobject_uevent_socket permissive=1
23:54:06,593 INFO systemd:Started plymouth-poweroff.service - Show Plymouth Power Off Screen.
23:54:06,695 NOTICE kernel:audit: type=1400 audit(1724889246.693:958): avc:  denied  { relabelto } for  pid=28620 comm="(udev-worker)" name="vcs63" dev="devtmpfs" ino=708 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:tty_device_t:s0 tclass=chr_file permissive=1
23:54:06,733 ERR anaconda:    h.flush()
23:54:06,733 ERR anaconda:  File "/usr/lib64/python3.12/logging/__init__.py", line 1143, in flush
23:54:06,735 ERR anaconda:    if self.stream and hasattr(self.stream, "flush"):
23:54:06,750 ERR anaconda:                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
23:54:06,750 ERR anaconda:  File "/sbin/anaconda", line 305, in <lambda>
23:54:06,794 ERR anaconda:    signal.signal(signal.SIGTERM, lambda num, frame: sys.exit(1))
23:54:06,796 ERR anaconda:                                                     ^^^^^^^^^^^
23:54:06,796 ERR anaconda:SystemExit: 1
23:54:06,869 INFO systemd:udisks2.service: Deactivated successfully.
23:54:06,869 INFO systemd:Stopped udisks2.service - Disk Manager.

virt-install.log

23:25:38,133 INFO systemd-logind:Removed session 1.
23:25:38,219 NOTICE udisksd:udisks daemon version 2.10.90 exiting
23:25:38,223 WARNING brltty:unsupported generic resource identifier: bluetooth:
23:25:38,229 INFO systemd:Received SIGRTMIN+20 from PID 30092 (plymouthd).
23:25:38,250 ERR anaconda:Exception ignored in atexit callback: <function shutdown at 0x7fc57a0b1e40>
23:25:38,250 ERR anaconda:Traceback (most recent call last):
23:25:38,295 ERR anaconda:  File "/usr/lib64/python3.12/logging/__init__.py", line 2263, in shutdown
23:25:38,345 INFO systemd:Started plymouth-poweroff.service - Show Plymouth Power Off Screen.

virt-install.log virt-install.log

[rvykydal]

First spotted 08-29-2024. 08-28-2024 does not have logs for a different issue. 08-27-2024 did not hit the problem.

Packages diff: lorax-packages.log.diff.txt

[rvykydal]

Last week occurence: 30 / 7 dailies which is 1/50 test runs.

[jkonecny12]

This is weird, it looks like the Anaconda is turning off the logging log gets released and somehow it changes into SIGTERM signal processing...

[jkonecny12]

I just saw this in the python documentation:

If you are implementing asynchronous signal handlers using the [signal](https://docs.python.org/3/library/signal.html#module-signal) module, you may not be able to use logging from within such handlers. This is because lock implementations in the [threading](https://docs.python.org/3/library/threading.html#module-threading) module are not always re-entrant, and so cannot be invoked from such signal handlers.

https://docs.python.org/3/library/logging.html#thread-safety

I wonder if this is not the issue we are hitting.

[rvykydal]

Since 10-11-2024 appearing also on daily-iso kstest.log virt-install.log I think it is caused by porting Wayland patches (https://github.com/rhinstaller/anaconda/pull/5829), adding image packages diff: lorax-packages.log.diff.txt Also: https://github.com/rhinstaller/anaconda/pull/5829#issuecomment-2374090151

[jkonecny12]

This should be resolved by https://github.com/rhinstaller/anaconda/pull/5962

[rvykydal]

This should be resolved by rhinstaller/anaconda#5962

Indeed, we haven't seen the issue since on daily-iso.