Description of problem: since some days, getting strange messages like these if calling yum: BDB2053 Freeing read locks for locker 0x1bf4: 4981/140246004406208 BDB2053 Freeing read locks for locker 0x1bf5: 4981/140246004406208 BDB2053 Freeing read locks for locker 0x1bf6: 4981/140246004406208 BDB2053 Freeing read locks for locker 0x1bf7: 4981/140246004406208 Version-Release number of selected component (if applicable): yum-3.4.3-51.fc18.noarch How reproducible: most times if calling yum Steps to Reproduce: 1. 2. 3. Actual results: BDB2053 Freeing read locks for locker 0x1bf4: 4981/140246004406208 BDB2053 Freeing read locks for locker 0x1bf5: 4981/140246004406208 BDB2053 Freeing read locks for locker 0x1bf6: 4981/140246004406208 BDB2053 Freeing read locks for locker 0x1bf7: 4981/140246004406208 Expected results: No such messages! Additional info: yum clean all does not help
Something is reading the rpmdb and either crashing while doing so or exiting without cleaning up (freeing database iterators etc), the messages come from rpm when cleaning up those stale locks left by something. Could be related to bug 907846 and bug 860500, in those cases something crashing (and invoking abrt which in turn involves reading rpmdb) while a transaction is running is at least one of the potential causes for stale locks and occasional hangs. Unfortunately the messages dont directly help identifying the troublemaker, but the audit system can help. Assuming you already have audit installed: # echo "-w /var/lib/rpm/Packages -p war -k rpmdb" >> /etc/audit/audit.rules # systemctl restart auditd.service After that, the next time that something has misbehaved and you get those "freeing read locks ...: <pid>/<tid>" messages, you can look rpmdb accessing processes by their pid with # ausearch -k rpmdb --pid <pid>
I found these records. Hope, it helps!: ======================================= type=SYSCALL msg=audit(1362552778.552:829): arch=c000003e syscall=2 success=yes exit=6 a0=23d7e10 a1=0 a2=0 a3=16 items=1 ppid=12068 pid=12069 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfined_u:system_r:abrt_helper_t:s0-s0:c0.c1023 key="rpmdb" type=SYSCALL msg=audit(1362552778.552:830): arch=c000003e syscall=2 success=yes exit=6 a0=23d7e10 a1=0 a2=0 a3=16 items=1 ppid=12068 pid=12069 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfined_u:system_r:abrt_helper_t:s0-s0:c0.c1023 key="rpmdb" type=SYSCALL msg=audit(1362554921.280:855): arch=c000003e syscall=2 success=yes exit=6 a0=1dce2c0 a1=0 a2=0 a3=16 items=1 ppid=12353 pid=12358 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="yumBackend.py" exe="/usr/bin/python2.7" subj=system_u:system_r:kernel_t:s0 key="rpmdb" type=SYSCALL msg=audit(1362554921.280:854): arch=c000003e syscall=2 success=yes exit=6 a0=1dce2c0 a1=0 a2=0 a3=16 items=1 ppid=12353 pid=12358 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="yumBackend.py" exe="/usr/bin/python2.7" subj=system_u:system_r:kernel_t:s0 key="rpmdb" type=SYSCALL msg=audit(1362556278.115:941): arch=c000003e syscall=2 success=yes exit=6 a0=2286e10 a1=0 a2=0 a3=16 items=1 ppid=12626 pid=12627 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfined_u:system_r:abrt_helper_t:s0-s0:c0.c1023 key="rpmdb" type=SYSCALL msg=audit(1362556278.115:942): arch=c000003e syscall=2 success=yes exit=6 a0=2286e10 a1=0 a2=0 a3=16 items=1 ppid=12626 pid=12627 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfined_u:system_r:abrt_helper_t:s0-s0:c0.c1023 key="rpmdb" type=SYSCALL msg=audit(1362558000.860:1351): arch=c000003e syscall=2 success=yes exit=6 a0=22ea4b0 a1=0 a2=0 a3=16 items=1 ppid=13441 pid=13444 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfined_u:system_r:abrt_helper_t:s0-s0:c0.c1023 key="rpmdb" type=SYSCALL msg=audit(1362558000.860:1352): arch=c000003e syscall=2 success=yes exit=6 a0=22ea4b0 a1=0 a2=0 a3=16 items=1 ppid=13441 pid=13444 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfined_u:system_r:abrt_helper_t:s0-s0:c0.c1023 key="rpmdb" type=SYSCALL msg=audit(1362561080.838:1410): arch=c000003e syscall=2 success=yes exit=6 a0=1ca14b0 a1=0 a2=0 a3=16 items=1 ppid=13914 pid=13915 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfined_u:system_r:abrt_helper_t:s0-s0:c0.c1023 key="rpmdb" type=SYSCALL msg=audit(1362561080.838:1411): arch=c000003e syscall=2 success=yes exit=6 a0=1ca14b0 a1=0 a2=0 a3=16 items=1 ppid=13914 pid=13915 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfined_u:system_r:abrt_helper_t:s0-s0:c0.c1023 key="rpmdb" type=SYSCALL msg=audit(1362565692.941:1511): arch=c000003e syscall=2 success=yes exit=6 a0=1e37560 a1=0 a2=0 a3=16 items=1 ppid=15600 pid=15601 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfined_u:system_r:abrt_helper_t:s0-s0:c0.c1023 key="rpmdb" type=SYSCALL msg=audit(1362565692.941:1512): arch=c000003e syscall=2 success=yes exit=6 a0=1e37560 a1=0 a2=0 a3=16 items=1 ppid=15600 pid=15601 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfined_u:system_r:abrt_helper_t:s0-s0:c0.c1023 key="rpmdb" type=SYSCALL msg=audit(1362565693.390:1513): arch=c000003e syscall=2 success=yes exit=17 a0=2a303f0 a1=0 a2=0 a3=16 items=1 ppid=15600 pid=15601 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfined_u:system_r:abrt_helper_t:s0-s0:c0.c1023 key="rpmdb" type=SYSCALL msg=audit(1362565693.390:1514): arch=c000003e syscall=2 success=yes exit=17 a0=2a303f0 a1=0 a2=0 a3=16 items=1 ppid=15600 pid=15601 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=2 tty=pts0 comm="yum" exe="/usr/bin/python2.7" subj=unconfine
Yes, that confirms its abrt that's causing problems. Thanks!
Oops, spoke too soon. Abrt is one of the players here but there are others too. To identify the troublemaker for sure, the pid of the "freeing read locks" message needs to be matched to those of audit logs. Taking the original message as an example: BDB2053 Freeing read locks for locker 0x1bf4: 4981/140246004406208 Here, the pid of the naughty process who left locks behind is 4981. So to search for the process that caused it, you need to do: # ausearch -k rpmdb --pid 4981
BDB2053 Freeing read locks for locker 0x291e: 31461/139831640917952 BDB2053 Freeing read locks for locker 0x291f: 31461/139831640917952 BDB2053 Freeing read locks for locker 0x2920: 31461/139831640917952 BDB2053 Freeing read locks for locker 0x2921: 31461/139831640917952 sudo ausearch -k rpmdb --pid 31461 ---- time->Wed Mar 6 15:00:11 2013 type=PATH msg=audit(1362578411.946:6169): item=0 name="/var/lib/rpm/Packages" inode=6554762 dev=08:01 mode=0100644 ouid=0 ogid=0 rdev=00:00 obj=unconfined_u:object_r:default_t:s0 type=CWD msg=audit(1362578411.946:6169): cwd="/var/tmp/abrt/pyhook-2013-03-06-15:00:11-31457" type=SYSCALL msg=audit(1362578411.946:6169): arch=c000003e syscall=2 success=yes exit=6 a0=ad9b20 a1=0 a2=0 a3=16 items=1 ppid=31460 pid=31461 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="abrt-action-sav" exe="/usr/bin/abrt-action-save-package-data" subj=system_u:system_r:kernel_t:s0 key="rpmdb" ---- time->Wed Mar 6 15:00:11 2013 type=PATH msg=audit(1362578411.946:6170): item=0 name="/var/lib/rpm/Packages" inode=6554762 dev=08:01 mode=0100644 ouid=0 ogid=0 rdev=00:00 obj=unconfined_u:object_r:default_t:s0 type=CWD msg=audit(1362578411.946:6170): cwd="/var/tmp/abrt/pyhook-2013-03-06-15:00:11-31457" type=SYSCALL msg=audit(1362578411.946:6170): arch=c000003e syscall=2 success=yes exit=6 a0=ad9b20 a1=0 a2=0 a3=16 items=1 ppid=31460 pid=31461 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="abrt-action-sav" exe="/usr/bin/abrt-action-save-package-data" subj=system_u:system_r:kernel_t:s0 key="rpmdb" ---- time->Wed Mar 6 15:00:11 2013 type=PATH msg=audit(1362578411.950:6171): item=0 name="/var/lib/rpm/Packages" inode=6554762 dev=08:01 mode=0100644 ouid=0 ogid=0 rdev=00:00 obj=unconfined_u:object_r:default_t:s0 type=CWD msg=audit(1362578411.950:6171): cwd="/var/tmp/abrt/pyhook-2013-03-06-15:00:11-31457" type=SYSCALL msg=audit(1362578411.950:6171): arch=c000003e syscall=2 success=yes exit=12 a0=b03030 a1=0 a2=0 a3=16 items=1 ppid=31460 pid=31461 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="abrt-action-sav" exe="/usr/bin/abrt-action-save-package-data" subj=system_u:system_r:kernel_t:s0 key="rpmdb" ---- time->Wed Mar 6 15:00:11 2013 type=PATH msg=audit(1362578411.950:6172): item=0 name="/var/lib/rpm/Packages" inode=6554762 dev=08:01 mode=0100644 ouid=0 ogid=0 rdev=00:00 obj=unconfined_u:object_r:default_t:s0 type=CWD msg=audit(1362578411.950:6172): cwd="/var/tmp/abrt/pyhook-2013-03-06-15:00:11-31457" type=SYSCALL msg=audit(1362578411.950:6172): arch=c000003e syscall=2 success=yes exit=12 a0=b03030 a1=0 a2=0 a3=16 items=1 ppid=31460 pid=31461 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="abrt-action-sav" exe="/usr/bin/abrt-action-save-package-data" subj=system_u:system_r:kernel_t:s0 key="rpmdb"
Okay, so it indeed is abrt. Thanks for verifying that.
Created attachment 776118 [details] Avoid leaving stale rpmdb locks behind So... finally stumbled on a reliable reproducer on my box and had a few minute to look at it. The problem is that abrt's rpm_get_package_nvr() doesn't free rpmdb iterator and transaction set on *successfull* exit, causing stale locks to be left behind, which next rpm invocation then cleans up (those "freeing read locks..." messages). Cases like this are exactly the reason why I tend to religiously stick to exactly one exit point per function, but attached is a minimal fix: Prior to the patch: [root@mursu ccpp-2013-07-03-21:57:48-23835]# /home/pmatilai/repos/abrt/src/daemon/abrt-action-save-package-data; rpm -q abrt BDB2053 Freeing read locks for locker 0x4e2: 18580/140024691308544 BDB2053 Freeing read locks for locker 0x4e3: 18580/140024691308544 BDB2053 Freeing read locks for locker 0x4e4: 18580/140024691308544 BDB2053 Freeing read locks for locker 0x4e5: 18580/140024691308544 abrt-2.1.5-1.fc19.x86_64 [root@mursu ccpp-2013-07-03-21:57:48-23835]# With the patch: [root@mursu ccpp-2013-07-03-21:57:48-23835]# /home/pmatilai/repos/abrt/src/daemon/abrt-action-save-package-data; rpm -q abrt abrt-2.1.5-1.fc19.x86_64 [root@mursu ccpp-2013-07-03-21:57:48-23835]# This bug is present in all current Fedora versions AFAICT, and is the cause of various other issues like bug 860500.
...and over to abrt (see above)
More precisely, this is the commit introducing the early return and the rpmdb iter/ts leak, which perhaps explains that this wasn't happening in F17, at least initially: commit fc97bbcfc4bfcc4463538698217d5c4869803c57 Author: Nikola Pajkovsky <npajkovs> Date: Thu Apr 26 12:19:20 2012 +0200 a-a-save-package-data: store package epoch, name, version, release and arch Signed-off-by: Nikola Pajkovsky <npajkovs>
Fixed in upstream git: commit 012486f76b39acb8e3431ff4290015a295011328 Author: Denys Vlasenko <dvlasenk> Date: Fri Jul 19 17:24:17 2013 +0200 abrt-action-save-package-data: properly close rpm database. Closes #674. RPM library uses Berkeley DB, which emits warnings like this if DB files weren't closed properly: BDB2053 Freeing read locks for locker 0x1e0: 28718/139661746636736 This change fixes it. Signed-off-by: Denys Vlasenko <dvlasenk> Signed-off-by: Jakub Filak <jfilak>
abrt-2.1.6-2.fc18,gnome-abrt-0.3.0-1.fc18,libreport-2.1.6-2.fc18 has been submitted as an update for Fedora 18. https://admin.fedoraproject.org/updates/abrt-2.1.6-2.fc18,gnome-abrt-0.3.0-1.fc18,libreport-2.1.6-2.fc18
Package abrt-2.1.6-2.fc18, gnome-abrt-0.3.0-1.fc18, libreport-2.1.6-2.fc18: * should fix your issue, * was pushed to the Fedora 18 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing abrt-2.1.6-2.fc18 gnome-abrt-0.3.0-1.fc18 libreport-2.1.6-2.fc18' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2013-13876/abrt-2.1.6-2.fc18,gnome-abrt-0.3.0-1.fc18,libreport-2.1.6-2.fc18 then log in and leave karma (feedback).
Um. The patch you guys applied is treating symptoms, not the actual disease. abrt-action-save-package-data might be the only place calling rpm_get_package_nvr() right now but with the applied patch, any possible future caller of that function will still leak rpmdb locks. All that was needed for a proper fix at the root of the issue was my patch from comment #7.
D'oh! Sorry, we missed your patch, but it has been already applied. Thank you! commit 02dd4e46c708a884ceb2c6a78fa1db1c51dc58cf
Package abrt-2.1.6-2.fc18, libreport-2.1.6-2.fc18, gnome-abrt-0.3.0-2.fc18: * should fix your issue, * was pushed to the Fedora 18 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing abrt-2.1.6-2.fc18 libreport-2.1.6-2.fc18 gnome-abrt-0.3.0-2.fc18' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2013-13876/abrt-2.1.6-2.fc18,gnome-abrt-0.3.0-2.fc18,libreport-2.1.6-2.fc18 then log in and leave karma (feedback).
Package abrt-2.1.6-3.fc18, libreport-2.1.6-2.fc18, gnome-abrt-0.3.0-2.fc18: * should fix your issue, * was pushed to the Fedora 18 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing abrt-2.1.6-3.fc18 libreport-2.1.6-2.fc18 gnome-abrt-0.3.0-2.fc18' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2013-13876/abrt-2.1.6-3.fc18,gnome-abrt-0.3.0-2.fc18,libreport-2.1.6-2.fc18 then log in and leave karma (feedback).
abrt-2.1.6-3.fc18, libreport-2.1.6-2.fc18, gnome-abrt-0.3.0-2.fc18 has been pushed to the Fedora 18 stable repository. If problems still persist, please make note of it in this bug report.
I'm seeing these messages on a freshly installed Fedora 25 laptop. I'm using dnf as normal and not doing anything "bad" like killing dnf (or any other process).
Bug 1398272 is one cause of them, and also there's a regression in rpm itself that causes stale locks left behind when terminated by a signal. But a three year old bug in abrt is not really the place to discuss these :)
I'am seeing these messages also, even though for the 1st time, on a F24 Cloud Image machine before the upgrade to F25. Again, never seen these messages before. I upgraded another machine of mine and did not get messages like this. $ sudo dnf system-upgrade reboot BDB2053 Freeing read locks for locker 0x21: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x23: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x24: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x25: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x26: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x27: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x28: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x29: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x2a: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x2b: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x2c: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x2d: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x2e: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x2f: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x30: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x31: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x32: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x33: 1231/140074723784448 BDB2053 Freeing read locks for locker 0x34: 1231/140074723784448
Again, an ages old abrt bug is entirely wrong place to discuss issues that might be happening *now*.
Hi, To add i am now receiving these issues as of the 28th February 2017 - so previous update may be causing this on the 27th February 2017. It may be the GUI based update as this presented an error when i ran "dnf" from the command line - so there may be a conflict. I have updates via the GUI set to once per month - but did notice that it has attempted to update every day since 27th February 2017. Checking for the process - dnf must have killed it as it is not listed. Regards, Shadders.