Bug 1761941
| Summary: | insights-client kills rpm/yum processes leaving stale lock files in the rpm database [rhel-7.9.z] | ||
|---|---|---|---|
| Product: | Red Hat Enterprise Linux 7 | Reporter: | Ryan Mullett <rmullett> |
| Component: | insights-client | Assignee: | jcrafts |
| Status: | CLOSED ERRATA | QA Contact: | Pavol Kotvan <pakotvan> |
| Severity: | high | Docs Contact: | |
| Priority: | high | ||
| Version: | 7.7 | CC: | agk, alrodrig, bernd.nies, cmoore, cww, dsynk, dwysocha, jcastran, jcrafts, jkubin, jreznik, kemyers, kwalker, link, millard.matt, pdwyer, rmetrich, svaughn, tscherf |
| Target Milestone: | rc | Keywords: | Reopened, ZStream |
| Target Release: | --- | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2020-12-15 11:23:37 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
I was able to reproduce RPM DB corruption by running this command:
COUNT=0; while true; do time /bin/timeout -s 9 0.2 /bin/rpm -qa --qf [name:%{NAME},epoch:%{EPOCH},version:%{VERSION},release:%{RELEASE},arch:%{ARCH},installtime:%{INSTALLTIME:date},buildtime:%{BUILDTIME},vendor:%{VENDOR},buildhost:%{BUILDHOST},sigpgp:%{SIGPGP:pgpsig}]; rpm -qa | grep insights; let COUNT+=1; echo "======COUNT: ${COUNT}======"; sleep 3; done
RPM DB became corrupted after 67 iterations.
By changing timeout signal to SIGTERM, above loop could iterate more than 200 times without corrupting the DB (I stopped while loop after so many iterations, it does not mean the DB got corrupted).
insights-client developers are preparing fix which will be released in next EGG release which should be this Thursday.
Fix for this issue was released in EGG/core version v 3.0.174. @Stephen,
Can you clarify how your previous update is a fix for this particular problem? Your comment indicates that version 3.0.174 includes the necessary change, but as of this morning there was another instance of this particular problem. I went ahead and registered a system with insights and checked the version included:
~]# yum install insights-client
~]# insights-client --register
~]# cd $(mktemp -d)
tmp.hCztyxd0qJ]# unzip /etc/insights-client/rpm.egg >/dev/null 2>&1
tmp.hCztyxd0qJ]# grep ^Version EGG-INFO/PKG-INFO
Version: 3.0.150
I assume that you mean that this particular change fixed the problem:
$ git show 5122e0d51f8d392bbeebff27f5a8fbab4bed8ba4
commit 5122e0d51f8d392bbeebff27f5a8fbab4bed8ba4
Author: Jeremy Crafts <gravitypriest.github.com>
Date: Thu Jul 16 10:24:15 2020 -0400
use SIGTERM for rpm and yum commands (#2630)
Signed-off-by: Jeremy Crafts <jcrafts>
diff --git a/insights/client/insights_spec.py b/insights/client/insights_spec.py
index 1e2de068..d0b9037b 100644
--- a/insights/client/insights_spec.py
+++ b/insights/client/insights_spec.py
@@ -47,8 +47,17 @@ class InsightsCommand(InsightsSpec):
# all commands should timeout after a long interval so the client does not hang
# prepend native nix 'timeout' implementation
- timeout_command = 'timeout -s KILL %s %s' % (
- self.config.cmd_timeout, self.command)
+
+ # use TERM for rpm/yum commands, KILL for everything else
+ if (self.command.startswith('/bin/rpm') or
+ self.command.startswith('yum') or
+ self.command.startswith('/usr/bin/yum')):
+ signal = 'TERM'
+ else:
+ signal = 'KILL'
+
+ timeout_command = 'timeout -s %s %s %s' % (
+ signal, self.config.cmd_timeout, self.command)
# ensure consistent locale for collected command output
cmd_env = {'LC_ALL': 'C',
But that is _not_ in the version pulled by my RHEL 7 client:
# awk '/InsightsCommand/,/timeout -s/' insights/client/insights_spec.py
class InsightsCommand(InsightsSpec):
'''
A command spec
'''
def __init__(self, config, spec, exclude, mountpoint, parent_pid=None):
InsightsSpec.__init__(self, config, spec, exclude, parent_pid)
self.command = spec['command'].replace(
'{CONTAINER_MOUNT_POINT}', mountpoint)
self.archive_path = mangle.mangle_command(self.command)
self.is_hostname = spec.get('symbolic_name') == 'hostname'
if not six.PY3:
self.command = self.command.encode('utf-8', 'ignore')
def get_output(self):
'''
Execute a command through system shell. First checks to see if
the requested command is executable. Returns (returncode, stdout, 0)
'''
# let systemd know we're still going
systemd_notify(self.parent_pid)
if self.is_hostname:
# short circuit for hostame with internal method
return determine_hostname()
# all commands should timeout after a long interval so the client does not hang
# prepend native nix 'timeout' implementation
timeout_command = 'timeout -s KILL %s %s' % (
I'm reopening this bug at this time.
Hello, Could you provide the output of insights-client --version? Also, are you receiving automatic egg updates? (i.e. in insights-client.conf, auto_updates=True) Thanks! Just for completeness, Discussion and internal investigation of the testing outcome mentioned in my previous update identified a separate issue which external end users would not be subject to. However, this does not preclude the failures being seen. The update dated "2020-07-16 19:48:52 UTC" indicating that the fix is present is applicable only to the auto-update behaviour. The core implementation that is shipped within the RPM is not updated at this time. Red Hat Enterprise Linux 7 shipped it's final minor release on September 29th, 2020. 7.9 was the last minor releases scheduled for RHEL 7. From intial triage it does not appear the remaining Bugzillas meet the inclusion criteria for Maintenance Phase 2 and will now be closed. From the RHEL life cycle page: https://access.redhat.com/support/policy/updates/errata#Maintenance_Support_2_Phase "During Maintenance Support 2 Phase for Red Hat Enterprise Linux version 7,Red Hat defined Critical and Important impact Security Advisories (RHSAs) and selected (at Red Hat discretion) Urgent Priority Bug Fix Advisories (RHBAs) may be released as they become available." If this BZ was closed in error and meets the above criteria please re-open it flag for 7.9.z, provide suitable business and technical justifications, and follow the process for Accelerated Fixes: https://source.redhat.com/groups/public/pnt-cxno/pnt_customer_experience_and_operations_wiki/support_delivery_accelerated_fix_release_handbook Feature Requests can re-opened and moved to RHEL 8 if the desired functionality is not already present in the product. Please reach out to the applicable Product Experience Engineer[0] if you have any questions or concerns. [0] https://bugzilla.redhat.com/page.cgi?id=agile_component_mapping.html&product=Red+Hat+Enterprise+Linux+7 Reopening and setting back to ASSIGNED due to the severity of the issue and that there is an ongoing effort towards fixing this problem 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 (insights-client bug fix and enhancement update), 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-2020:5462 |
Description of problem: insights-client kills rpm/yum processes leaving stale lock files in the rpm database at /var/lib/rpm/__db* Version-Release number of selected component (if applicable): insights-client-3.0.6-2.el7_6.noarch How reproducible: Always, on specific systems. Never on other systems. Steps to Reproduce: Have a yum process running while insights-client does automatically scheduled run Actual results: insights-client kills yum process leaving lock files in the rpm database Expected results: insights-client will not kill yum processes Additional info: Here's the data that was utilized to come to this conclusion: From audit logs here's the yum pid (22351) that created the lock files. We have an audit set up to log every rpm database modification: type=PROCTITLE msg=audit(1571031348.818:17961): proctitle=72706D002D71002D2D716600257B56455253494F4E7D2D257B52454C454153457D00696E7369676874732D636C69656E74 type=SYSCALL msg=audit(1571031356.824:17962): arch=c000003e syscall=2 success=yes exit=3 a0=109f070 a1=42 a2=1a4 a3=3 items=2 ppid=22350 pid=22351 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="yum" exe="/usr/bin/python2.7" key="rpm" type=CWD msg=audit(1571031356.824:17962): cwd="/" type=PATH msg=audit(1571031356.824:17962): item=0 name="/var/lib/rpm/" inode=67155796 dev=fd:00 mode=040755 ouid=0 ogid=0 rdev=00:00 objtype=PARENT cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0 type=PATH msg=audit(1571031356.824:17962): item=1 name="/var/lib/rpm/.dbenv.lock" inode=67155797 dev=fd:00 mode=0100644 ouid=0 ogid=0 rdev=00:00 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0 type=PROCTITLE msg=audit(1571031356.824:17962): proctitle=2F7573722F62696E2F707974686F6E002F7573722F62696E2F79756D002D43007265706F6C697374 type=SYSCALL msg=audit(1571031356.824:17963): arch=c000003e syscall=2 success=no exit=-17 a0=1099f60 a1=c2 a2=1a4 a3=2 items=2 ppid=22350 pid=22351 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="yum" exe="/usr/bin/python2.7" key="rpm" type=CWD msg=audit(1571031356.824:17963): cwd="/" type=PATH msg=audit(1571031356.824:17963): item=0 name="/var/lib/rpm/" inode=67155796 dev=fd:00 mode=040755 ouid=0 ogid=0 rdev=00:00 objtype=PARENT cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0 type=PATH msg=audit(1571031356.824:17963): item=1 name="/var/lib/rpm/__db.001" inode=67167052 dev=fd:00 mode=0100644 ouid=0 ogid=0 rdev=00:00 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0 type=PROCTITLE msg=audit(1571031356.824:17963): proctitle=2F7573722F62696E2F707974686F6E002F7573722F62696E2F79756D002D43007265706F6C697374 type=SYSCALL msg=audit(1571031356.824:17964): arch=c000003e syscall=2 success=yes exit=4 a0=1099f60 a1=2 a2=0 a3=2 items=1 ppid=22350 pid=22351 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="yum" exe="/usr/bin/python2.7" key="rpm" type=CWD msg=audit(1571031356.824:17964): cwd="/" type=PATH msg=audit(1571031356.824:17964): item=0 name="/var/lib/rpm/__db.001" inode=67167052 dev=fd:00 mode=0100644 ouid=0 ogid=0 rdev=00:00 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0 type=PROCTITLE msg=audit(1571031356.824:17964): proctitle=2F7573722F62696E2F707974686F6E002F7573722F62696E2F79756D002D43007265706F6C697374 type=SYSCALL msg=audit(1571031356.824:17965): arch=c000003e syscall=2 success=yes exit=4 a0=1099f60 a1=2 a2=1a4 a3=2 items=1 ppid=22350 pid=22351 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="yum" exe="/usr/bin/python2.7" key="rpm" type=CWD msg=audit(1571031356.824:17965): cwd="/" type=PATH msg=audit(1571031356.824:17965): item=0 name="/var/lib/rpm/__db.001" inode=67167052 dev=fd:00 mode=0100644 ouid=0 ogid=0 rdev=00:00 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0 type=PROCTITLE msg=audit(1571031356.824:17965): proctitle=2F7573722F62696E2F707974686F6E002F7573722F62696E2F79756D002D43007265706F6C697374 type=SYSCALL msg=audit(1571031356.824:17966): arch=c000003e syscall=2 success=yes exit=6 a0=107b4c0 a1=42 a2=1a4 a3=2 items=2 ppid=22350 pid=22351 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="yum" exe="/usr/bin/python2.7" key="rpm" type=CWD msg=audit(1571031356.824:17966): cwd="/" =============================================================================================================================== We have a debugging application installed in the client that tracks every kill signal that is generated on the system. This was used in combination with the above audit logs to see what killed the pid that created the locks listed in audit logs. This allows us to see that the insights-client was the application that killed the yum process: Mon Oct 14 01:36:25 2019 EDT: sys.kill: swapper/0[0] -> systemd[1] -> insights-client[22230] -> insights-client[22317] -> timeout[22342] -> python[22343] -> timeout(22350) called kill 22351, SIGKILL killed yum Mon Oct 14 01:36:25 2019 EDT: sig.send: SIGKILL was sent to yum (pid:22351) by swapper/0[0] -> systemd[1] -> insights-client[22230] -> insights-client[22317] -> timeout[22342] -> python[22343] -> timeout (pid:22350) uid:0 using signal_generate Mon Oct 14 01:36:25 2019 EDT: sys.kill: swapper/0[0] -> systemd[1] -> insights-client[22230] -> insights-client[22317] -> timeout[22342] -> python[22343] -> timeout(22350) called kill 0, SIGKILL killed Mon Oct 14 01:36:25 2019 EDT: sig.send: SIGKILL was sent to yum (pid:22351) by swapper/0[0] -> systemd[1] -> insights-client[22230] -> insights-client[22317] -> timeout[22342] -> python[22343] -> timeout (pid:22350) uid:0 using signal_generate =============================================================================================================================== Just to be thorough, and to make sure that the pid lines up, I confirmed that the locks in the rpm database we analyzed were created by the same pid: # db_stat -CA -h . Default locking region information: 1222 Last allocated locker ID 0x7fffffff Current maximum unused locker ID 5 Number of lock modes 100 Initial number of locks allocated 0 Initial number of lockers allocated 100 Initial number of lock objects allocated 0 Maximum number of locks possible 0 Maximum number of lockers possible 0 Maximum number of lock objects possible 100 Current number of locks allocated 18 Current number of lockers allocated 100 Current number of lock objects allocated 20 Number of lock object partitions 1031 Size of object hash table 2 Number of current locks 29 Maximum number of locks at any one time 3 Maximum number of locks in any one bucket 0 Maximum number of locks stolen by for an empty partition 0 Maximum number of locks stolen for any one partition 2 Number of current lockers 18 Maximum number of lockers at any one time 2 Number of current lock objects 25 Maximum number of lock objects at any one time 2 Maximum number of lock objects in any one bucket 0 Maximum number of objects stolen by for an empty partition 0 Maximum number of objects stolen for any one partition 1807327 Total number of locks requested 1807324 Total number of locks released 0 Total number of locks upgraded 908 Total number of locks downgraded 0 Lock requests not available due to conflicts, for which we waited 0 Lock requests not available due to conflicts, for which we did not wait 0 Number of deadlocks 0 Lock timeout value 0 Number of locks that have timed out 0 Transaction timeout value 0 Number of transactions that have timed out 280KB Region size 0 The number of partition locks that required waiting (0%) 0 The maximum number of times any partition lock was waited for (0%) 0 The number of object queue operations that required waiting (0%) 0 The number of locker allocations that required waiting (0%) 0 The number of region locks that required waiting (0%) 2 Maximum hash bucket length =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Lock REGINFO information: Environment Region type 1 Region ID ./__db.001 Region name 0x7f59a0d14000 Region address 0x7f59a0d140a0 Region allocation head 0x7f59a0d146a8 Region primary address 0 Region maximum allocation 0 Region allocated Region allocations: 101 allocations, 0 failures, 0 frees, 1 longest Allocations by power-of-two sizes: 1KB 97 2KB 1 4KB 1 8KB 0 16KB 0 32KB 1 64KB 0 128KB 1 256KB 0 512KB 0 1024KB 0 REGION_SHARED Region flags =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Lock region parameters: 2 Lock region region mutex [0/1415 0% 23/140022927968064] 131 locker table size 1031 object table size 2320 obj_off 111448 locker_off 0 need_dd =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Lock conflict matrix: =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Locks grouped by lockers: Locker Mode Count Status ----------------- Object --------------- 4c5 dd= 0 locks held 1 write locks 0 pid/thread 22351/140325946337088 flags 0 priority 100 4c5 READ 1 HELD (201342d fd00 6f89e70e 3000 0) handle 0 4c6 dd= 0 locks held 1 write locks 0 pid/thread 22351/140325946337088 flags 0 priority 100 4c6 READ 2 HELD 0x1e5e0 len: 20 data: 2d34010200fd00000ee7896f0030000000000000 =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Locks grouped by object: Locker Mode Count Status ----------------- Object --------------- 4c6 READ 2 HELD 0x1e5e0 len: 20 data: 2d34010200fd00000ee7896f0030000000000000 4c5 READ 1 HELD (201342d fd00 6f89e70e 3000 0) handle 0 =============================================================================================================================== Note in the above, under "Lock conflict matrix:" we can see that the pid that created those locks is 22351, which lines up with the pid of the yum process, as well as the pid that was killed by insights-client. The insights-client config, as well as the redhat-access-insights.conf configs are both in default state. The insights-client on the hosts having the issues is set to autorun via the --enable-schedule option. We have disabled automatic scheduling on the hosts in question in order to see if we can reproduce this without it enabled.