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.

Sign up for GitHub

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

Jump to bottom

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

Open
rvykydal opened this issue Sep 2, 2024 · 7 comments
Open

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

rvykydal opened this issue Sep 2, 2024 · 7 comments
Labels
rhel10 test flake A test flake worth tracking (for more investigation, potenital bug, or to see if more come...)

Comments

@rvykydal
Copy link
Contributor

rvykydal commented Sep 2, 2024 •
edited
Loading

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 rvykydal added test flake A test flake worth tracking (for more investigation, potenital bug, or to see if more come...) rhel10 labels Sep 2, 2024
@rvykydal
Copy link
Contributor Author

rvykydal commented Sep 2, 2024

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 rvykydal mentioned this issue Sep 3, 2024
Merged
@rvykydal
Copy link
Contributor Author

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

@jkonecny12
Copy link
Member

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
Copy link
Member

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.

@jkonecny12 jkonecny12 mentioned this issue Sep 25, 2024
Merged
9 tasks
@rvykydal
Copy link
Contributor Author

rvykydal commented Oct 15, 2024 •
edited
Loading

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

@rvykydal rvykydal changed the title rhel-10 tests flakes failing at the end of installation with ERR anaconda:Exception ignored in atexit callback: <function shutdown at 0x7f81dbab1e40>"" rhel-10 and daily-iso tests flakes failing at the end of installation with ERR anaconda:Exception ignored in atexit callback: <function shutdown at 0x7f81dbab1e40>"" Oct 15, 2024
jkonecny12 added a commit to jkonecny12/anaconda that referenced this issue Oct 15, 2024
@jkonecny12
Suppress tracebacks when SIGTERM signal processing
60578f9 
This is a workaround for
rhinstaller/kickstart-tests#1296

where we are most likely hitting issue that logging is not safe to use
in the signal handlers because logging is not reentrant safe. To avoid
failures in KS tests and also test if this is the correct issue, let's
use this workaround.

The ideal fix should be to not use logging in atexit call which might be
tricky to resolve and also we will use a lot of log outputs.
@jkonecny12 jkonecny12 mentioned this issue Oct 15, 2024
Closed
jkonecny12 added a commit to jkonecny12/anaconda that referenced this issue Oct 16, 2024
@jkonecny12
Suppress tracebacks when SIGTERM signal processing
645d5bf 
This is a workaround for
rhinstaller/kickstart-tests#1296

where we are most likely hitting issue that logging is not safe to use
in the signal handlers because logging is not reentrant safe. To avoid
failures in KS tests and also test if this is the correct issue, let's
use this workaround.

The ideal fix should be to not use logging in atexit call which might be
tricky to resolve and also we will use a lot of log outputs.
jkonecny12 added a commit to jkonecny12/anaconda that referenced this issue Oct 17, 2024
@jkonecny12
Suppress tracebacks when SIGTERM signal processing
9ef1d02 
This is a workaround for
rhinstaller/kickstart-tests#1296

where we are most likely hitting issue that logging is not safe to use
in the signal handlers because logging is not reentrant safe. To avoid
failures in KS tests and also test if this is the correct issue, let's
use this workaround.

The ideal fix should be to not use logging in atexit call which might be
tricky to resolve and also we will use a lot of log outputs.
@jkonecny12
Copy link
Member

This should be resolved by rhinstaller/anaconda#5962

@rvykydal
Copy link
Contributor Author

This should be resolved by rhinstaller/anaconda#5962

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

@rvykydal rvykydal changed the title rhel-10 and daily-iso tests flakes failing at the end of installation with ERR anaconda:Exception ignored in atexit callback: <function shutdown at 0x7f81dbab1e40>"" rhel-10 tests flakes failing at the end of installation with ERR anaconda:Exception ignored in atexit callback: <function shutdown at 0x7f81dbab1e40>"" Nov 19, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
rhel10 test flake A test flake worth tracking (for more investigation, potenital bug, or to see if more come...)
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@rvykydal @jkonecny12