Note: This bug is displayed in read-only format because
the product is no longer active in Red Hat Bugzilla.
RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Description of problem:
Customer having tons of AVCs popping up regularly sees his setroubleshootd service die while updating the database:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot self.prune()
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot self.save()
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot Traceback (most recent call last):
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot self.delete_signature(sig, prune=True)"
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot File ""/usr/lib64/python2.7/site-packages/setroubleshoot/analyze.py"", line 377, in auto_save_callback"
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot File ""/usr/lib64/python2.7/site-packages/setroubleshoot/analyze.py"", line 355, in save"
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot File ""/usr/lib64/python2.7/site-packages/setroubleshoot/analyze.py"", line 320, in prune"
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot File ""/usr/lib64/python2.7/site-packages/setroubleshoot/analyze.py"", line 437, in delete_signature"
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot siginfo = self.lookup_signature(sig)
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot raise ProgramError(ERR_NO_SIGNATURE_MATCH)
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot File ""/usr/lib64/python2.7/site-packages/setroubleshoot/analyze.py"", line 399, in lookup_signature"
Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot setroubleshoot.errcode.ProgramError: [Errno 1001] signature not found
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
This is due to multiple threads cleaning up the database concurrently, even though no locking mechanism is implemented in the daemon.
Version-Release number of selected component (if applicable):
setroubleshoot-server-3.2.29-3.el7.x86_64
How reproducible:
Regularly on customer's site. Tried in my lab but failed for now (but tried not really hard).
A scenario is having more than max_alerts (50 by default) alerts in database, causing auto_save_callback to clean up the database.
While cleanup is happening, some new alert should be raised, causing another thread to perform the same cleanup.
Additional info:
After modifying the code to print out the Thread name (hack in log_debug(), util.py) and tuning log level to Debug, the customer hit the issue and analysis below shows clearly the concurrent modification of the database happening.
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
import threading <<< ADD THIS
def log_debug(msg):
global log_level
if log_level >= syslog.LOG_DEBUG:
syslog.syslog(syslog.LOG_DEBUG, "Thread %s: %s" % (threading.currentThread().name, msg)) <<< AMEND THIS LINE
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
Analysis of occurrence:
MainThread does automatic saving of the database a 08:30:57, causing pruning of 80 alerts because number of alerts in database is greater than default max_alerts (50):
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: writing database (/var/lib/setroubleshoot/setroubleshoot_database.xml) modified_count=194
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: auto_save database (/var/lib/setroubleshoot/setroubleshoot_database.xml) modified_count=194
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=...
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: prune first 80 alerts, len(sigs=80 sigs=[...
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=...
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=...
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=...
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=...
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=...
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=...
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00
Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: writing database (/var/lib/setroubleshoot/setroubleshoot_database.xml) modified_count=201
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
At the same time Thread-1 wants to write to the database because a new AVC popped up:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: analyze_avc() avc=scontext=system_u:system_r:logrotate_t:s0-s0:c0.c1023 tcontext=system_u:object_r:udev_rules_t:s0 access=['getattr'] tclass=file tpath=/etc/udev/rules.d/70-persistent-ipoib.rules
Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: lookup_signature: found 0 matches with scores
Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: not in database yet
Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: writing database (/var/lib/setroubleshoot/setroubleshoot_database.xml) modified_count=202
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
However, because too many alerts are in the database, Thread-1 also proceeded with the database cleanup:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: prune first 74 alerts, len(sigs=74 sigs=...
Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: delete_signature: sig=...
Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: lookup_signature: found 1 matches with scores 1.00
Oct 4 08:30:58 XXX setroubleshoot: Thread Thread-1: writing database (/var/lib/setroubleshoot/setroubleshoot_database.xml) modified_count=203
Oct 4 08:30:58 XXX setroubleshoot: Thread MainThread: delete_signature: sig=...
Oct 4 08:30:58 XXX setroubleshoot: Thread MainThread: lookup_signature: found 0 matches with scores
Oct 4 08:30:58 XXX setroubleshoot: Thread Thread-1: delete_signature: sig=...
...
Oct 4 08:30:58 XXX setroubleshoot: Thread Thread-1: delete_signature: sig=...
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
On the last line, setroubleshootd died due to the error above.
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.
For information on the advisory, and where to find the updated
files, follow the link below.
If the solution does not work for you, open a new bug report.
https://access.redhat.com/errata/RHBA-2019:2168
Description of problem: Customer having tons of AVCs popping up regularly sees his setroubleshootd service die while updating the database: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot self.prune() Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot self.save() Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot Traceback (most recent call last): Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot self.delete_signature(sig, prune=True)" Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot File ""/usr/lib64/python2.7/site-packages/setroubleshoot/analyze.py"", line 377, in auto_save_callback" Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot File ""/usr/lib64/python2.7/site-packages/setroubleshoot/analyze.py"", line 355, in save" Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot File ""/usr/lib64/python2.7/site-packages/setroubleshoot/analyze.py"", line 320, in prune" Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot File ""/usr/lib64/python2.7/site-packages/setroubleshoot/analyze.py"", line 437, in delete_signature" Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot siginfo = self.lookup_signature(sig) Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot raise ProgramError(ERR_NO_SIGNATURE_MATCH) Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot File ""/usr/lib64/python2.7/site-packages/setroubleshoot/analyze.py"", line 399, in lookup_signature" Oct 4 08:30:58 XXX org.fedoraproject.Setroubleshoot setroubleshoot.errcode.ProgramError: [Errno 1001] signature not found -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- This is due to multiple threads cleaning up the database concurrently, even though no locking mechanism is implemented in the daemon. Version-Release number of selected component (if applicable): setroubleshoot-server-3.2.29-3.el7.x86_64 How reproducible: Regularly on customer's site. Tried in my lab but failed for now (but tried not really hard). A scenario is having more than max_alerts (50 by default) alerts in database, causing auto_save_callback to clean up the database. While cleanup is happening, some new alert should be raised, causing another thread to perform the same cleanup. Additional info: After modifying the code to print out the Thread name (hack in log_debug(), util.py) and tuning log level to Debug, the customer hit the issue and analysis below shows clearly the concurrent modification of the database happening. -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- import threading <<< ADD THIS def log_debug(msg): global log_level if log_level >= syslog.LOG_DEBUG: syslog.syslog(syslog.LOG_DEBUG, "Thread %s: %s" % (threading.currentThread().name, msg)) <<< AMEND THIS LINE -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- Analysis of occurrence: MainThread does automatic saving of the database a 08:30:57, causing pruning of 80 alerts because number of alerts in database is greater than default max_alerts (50): -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: writing database (/var/lib/setroubleshoot/setroubleshoot_database.xml) modified_count=194 Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: auto_save database (/var/lib/setroubleshoot/setroubleshoot_database.xml) modified_count=194 Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00 Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00 Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=... Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: prune first 80 alerts, len(sigs=80 sigs=[... Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=... Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00 Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00 Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00 Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=... Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00 Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=... Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=... Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=... Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: delete_signature: sig=... Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: lookup_signature: found 1 matches with scores 1.00 Oct 4 08:30:57 XXX setroubleshoot: Thread MainThread: writing database (/var/lib/setroubleshoot/setroubleshoot_database.xml) modified_count=201 -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- At the same time Thread-1 wants to write to the database because a new AVC popped up: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: analyze_avc() avc=scontext=system_u:system_r:logrotate_t:s0-s0:c0.c1023 tcontext=system_u:object_r:udev_rules_t:s0 access=['getattr'] tclass=file tpath=/etc/udev/rules.d/70-persistent-ipoib.rules Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: lookup_signature: found 0 matches with scores Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: not in database yet Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: writing database (/var/lib/setroubleshoot/setroubleshoot_database.xml) modified_count=202 -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- However, because too many alerts are in the database, Thread-1 also proceeded with the database cleanup: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: prune first 74 alerts, len(sigs=74 sigs=... Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: delete_signature: sig=... Oct 4 08:30:57 XXX setroubleshoot: Thread Thread-1: lookup_signature: found 1 matches with scores 1.00 Oct 4 08:30:58 XXX setroubleshoot: Thread Thread-1: writing database (/var/lib/setroubleshoot/setroubleshoot_database.xml) modified_count=203 Oct 4 08:30:58 XXX setroubleshoot: Thread MainThread: delete_signature: sig=... Oct 4 08:30:58 XXX setroubleshoot: Thread MainThread: lookup_signature: found 0 matches with scores Oct 4 08:30:58 XXX setroubleshoot: Thread Thread-1: delete_signature: sig=... ... Oct 4 08:30:58 XXX setroubleshoot: Thread Thread-1: delete_signature: sig=... -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- On the last line, setroubleshootd died due to the error above.