Bug 1422147

Summary: Traceback when installing a package at the end of anaconda installation
Product: Red Hat Enterprise Linux 8 Reporter: Nikolai Sednev <nsednev>
Component: anacondaAssignee: Anaconda Maintenance Team <anaconda-maint-list>
Status: CLOSED CURRENTRELEASE QA Contact: Release Test Team <release-test-team-automation>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 8.0CC: amcnabb, awilliam, bugs, extras-qa, ffesti, james.antill, jonathan, jstodola, maurizio.antillon, maxamillion, pmatilai, redhat-bugzilla, tim.lauridsen, vanmeeuwen+fedora, zpavlas
Target Milestone: rcKeywords: CommonBugs
Target Release: 8.1   
Hardware: x86_64   
OS: Linux   
Whiteboard: https://fedoraproject.org/wiki/Common_F16_bugs#anaconda-kickstart-post
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 730857 Environment:
Last Closed: 2020-09-25 17:37:55 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 730857    
Bug Blocks: 713564    
Attachments:
Description Flags
sosreport-alma04.qa.lab.tlv.redhat.com-20170214171236.tar.xz none

Description Nikolai Sednev 2017-02-14 15:18:03 UTC
+++ This bug was initially created as a clone of Bug #730857 +++

There's a bug observed in RHEL testing which we assume to be present in Fedora 16 as well.

"When installing packages in "%post" section of kickstart installation or
manually in chroot before restarting the installation, yum throws a traceback:

Traceback (most recent call last):
  File "/usr/bin/yum", line 29, in <module>
    yummain.user_main(sys.argv[1:], exit_code=True)
  File "/usr/share/yum-cli/yummain.py", line 276, in user_main
    errcode = main(args)
  File "/usr/share/yum-cli/yummain.py", line 211, in main
    return_code = base.doTransaction()
  File "/usr/share/yum-cli/cli.py", line 586, in doTransaction
    resultobject = self.runTransaction(cb=cb)
  File "/usr/lib/python2.6/site-packages/yum/__init__.py", line 1436, in
runTransaction
    lastdbv = self.history.last()
  File "/usr/lib/python2.6/site-packages/yum/history.py", line 1259, in last
    ret = self.old([], 1, complete_transactions_only)
  File "/usr/lib/python2.6/site-packages/yum/history.py", line 1208, in old
    executeSQL(cur, sql, params)
  File "/usr/lib/python2.6/site-packages/yum/sqlutils.py", line 166, in
executeSQLQmark
    return cursor.execute(query)
sqlite3.OperationalError: database is locked"

"Looking through the patches changed from -17 to -18 I see this which feels
completely dead on:


-- a/yum/history.py
+++ b/yum/history.py
@@ -627,6 +627,14 @@ class YumHistory:
                 self.conf.readable = False
                 return None

+            #  Note that this is required due to changing the history DB in
the
+            # callback for removed txmbrs ... which happens inside the chroot,
+            # as against all our other access which is outside the chroot. So
+            # we need sqlite to not open the journal.
+            #  In theory this sucks, as history could be shared. In reality
+            # it's deep yum stuff and there should only be one yum.
+            executeSQL(self._conn.cursor(), "PRAGMA locking_mode = EXCLUSIVE")
+
         return self._conn.cursor()
     def _commit(self):

Since at the point in the anaconda run you have 2 yums (sorta) one inside
anaconda and the one you're execing in %post."

This is a significant issue for kickstart installs. Proposing as Beta blocker (to feed into the discussion we need to have on kickstart criteria) and marking as CommonBugs.

--- Additional comment from Panu Matilainen on 2011-08-16 02:52:29 EDT ---

The exclusive sqlite access mode is largely a hack to deal with chroot issues, but me thinks this is a case of it simply exposing a flaw in the way things have been done so far: there shouldn't be two yum instances running on the same system, and this should be dealt with in anaconda by fully shutting down its internal yum instance before entering %post (it doesn't need it at that point for anything).

--- Additional comment from seth vidal on 2011-08-16 15:30:06 EDT ---

Agreed on the anaconda changes. The comment I made above was to deal w/the issue pre-6.2 - not to suggest that yum solve it all internally.

--- Additional comment from James Antill on 2011-08-17 15:34:05 EDT ---

 Note that we already have a yb.history.close() API ... and it'll automatically do it when "freed", so unless you want us to automatically do it at the end of the transaction (kind of icky, but probably nothing breaks) ... then I guess we just need to change anaconda.

--- Additional comment from Fedora Update System on 2011-08-30 15:51:52 EDT ---

anaconda-16.16-1.fc16 has been submitted as an update for Fedora 16.
https://admin.fedoraproject.org/updates/anaconda-16.16-1.fc16

--- Additional comment from Fedora Update System on 2011-08-30 22:30:56 EDT ---

anaconda-16.16-1.fc16 has been pushed to the Fedora 16 stable repository.  If problems still persist, please make note of it in this bug report.

--- Additional comment from Chris Lumens on 2011-09-05 15:24:35 EDT ---




I've failed to install rhvm-appliance-4.1.20170126.0-1.el7ev.noarch.rpm package on RHEVH4.1 host with these components:
sanlock-3.4.0-1.el7.x86_64
ovirt-node-ng-nodectl-4.1.0-0.20170104.1.el7.noarch
qemu-kvm-rhev-2.6.0-28.el7_3.3.x86_64
vdsm-4.19.4-1.el7ev.x86_64
ovirt-imageio-common-1.0.0-0.el7ev.noarch
ovirt-engine-sdk-python-3.6.9.1-1.el7ev.noarch
ovirt-setup-lib-1.1.0-1.el7ev.noarch
ovirt-vmconsole-host-1.0.4-1.el7ev.noarch
mom-0.5.8-1.el7ev.noarch
ovirt-imageio-daemon-1.0.0-0.el7ev.noarch
ovirt-hosted-engine-ha-2.1.0.1-1.el7ev.noarch
ovirt-hosted-engine-setup-2.1.0.1-1.el7ev.noarch
ovirt-vmconsole-1.0.4-1.el7ev.noarch
libvirt-client-2.0.0-10.el7_3.4.x86_64
ovirt-host-deploy-1.6.0-1.el7ev.noarch
Linux version 3.10.0-514.6.1.el7.x86_64 (mockbuild.eng.bos.redhat.com) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-11) (GCC) ) #1 SMP Sat Dec 10 11:15:38 EST 2016
Linux 3.10.0-514.6.1.el7.x86_64 #1 SMP Sat Dec 10 11:15:38 EST 2016 x86_64 x86_64 x86_64 GNU/Linux
Red Hat Enterprise Linux release 7.3

Marking /var/tmp/yum-root-xHybhj/rhvm-appliance-4.1.20170126.0-1.el7ev.noarch.rpm to be installed
Resolving Dependencies
--> Running transaction check
---> Package rhvm-appliance.noarch 1:4.1.20170126.0-1.el7ev will be installed
--> Finished Dependency Resolution

Dependencies Resolved

======================================================================================================================
 Package            Arch       Version                        Repository                                         Size
======================================================================================================================
Installing:
 rhvm-appliance     noarch     1:4.1.20170126.0-1.el7ev       /rhvm-appliance-4.1.20170126.0-1.el7ev.noarch     1.6 G

Transaction Summary
======================================================================================================================
Install  1 Package

Total size: 1.6 G
Installed size: 1.6 G
Downloading packages:
Running transaction check
Running transaction test
Transaction test succeeded
Running transaction
Traceback (most recent call last):
  File "/usr/bin/yum", line 29, in <module>
    yummain.user_main(sys.argv[1:], exit_code=True)
  File "/usr/share/yum-cli/yummain.py", line 370, in user_main
    errcode = main(args)
  File "/usr/share/yum-cli/yummain.py", line 276, in main
    return_code = base.doTransaction()
  File "/usr/share/yum-cli/cli.py", line 773, in doTransaction
    resultobject = self.runTransaction(cb=cb)
  File "/usr/lib/python2.7/site-packages/yum/__init__.py", line 1833, in runTransaction
    lastdbv = self.history.last()
  File "/usr/lib/python2.7/site-packages/yum/history.py", line 1271, in last
    ret = self.old([], 1, complete_transactions_only)
  File "/usr/lib/python2.7/site-packages/yum/history.py", line 1220, in old
    executeSQL(cur, sql, params)
  File "/usr/lib/python2.7/site-packages/yum/sqlutils.py", line 166, in executeSQLQmark
    return cursor.execute(query)
sqlite3.OperationalError: database is locked

Comment 1 Nikolai Sednev 2017-02-14 15:19:54 UTC
Created attachment 1250279 [details]
sosreport-alma04.qa.lab.tlv.redhat.com-20170214171236.tar.xz

Comment 3 Sandro Bonazzola 2019-07-02 13:11:16 UTC
Didn't make it in RHEL 7, moving out to RHEL 8
Can you please try to reproduce on EL8 image when available?

Comment 5 Jan Stodola 2020-09-25 17:37:55 UTC
Nikolai,
I'm not able to reproduce this bug on RHEL-8.3 with anaconda-33.16.3.24-1.el8 and the following %post section:

%post
cat <<"EOF" >/etc/yum.repos.d/custom-repo.repo
[custom-repo]
name=custom-repo
baseurl=<REPO_URL>
enabled=1
gpgcheck=0
EOF

yum -y install zsh
%end

From /var/log/anaconda/program.log after the installation:

17:32:17,922 INF program: Dependencies resolved.
17:32:17,922 INF program: ================================================================================
17:32:17,922 INF program: Package     Architecture   Version                   Repository           Size
17:32:17,922 INF program: ================================================================================
17:32:17,922 INF program: Installing:
17:32:17,922 INF program: zsh         x86_64         5.5.1-6.el8_1.2           custom-repo         2.9 M
17:32:17,923 INF program: 
17:32:17,923 INF program: Transaction Summary
17:32:17,923 INF program: ================================================================================
17:32:17,923 INF program: Install  1 Package
17:32:17,923 INF program: 
17:32:17,923 INF program: Total download size: 2.9 M
17:32:17,923 INF program: Installed size: 7.2 M
17:32:17,923 INF program: Downloading Packages:
17:32:17,923 INF program: zsh-5.5.1-6.el8_1.2.x86_64.rpm                   21 MB/s | 2.9 MB     00:00
17:32:17,923 INF program: --------------------------------------------------------------------------------
17:32:17,923 INF program: Total                                            20 MB/s | 2.9 MB     00:00
17:32:17,923 INF program: Running transaction check
17:32:17,924 INF program: Transaction check succeeded.
17:32:17,924 INF program: Running transaction test
17:32:17,924 INF program: Transaction test succeeded.
17:32:17,924 INF program: Running transaction
17:32:17,924 INF program: Preparing        :                                                        1/1
17:32:17,924 INF program: Installing       : zsh-5.5.1-6.el8_1.2.x86_64                             1/1
17:32:17,924 INF program: Running scriptlet: zsh-5.5.1-6.el8_1.2.x86_64                             1/1
17:32:17,924 INF program: Verifying        : zsh-5.5.1-6.el8_1.2.x86_64                             1/1
17:32:17,924 INF program: Installed products updated.
17:32:17,924 INF program: 
17:32:17,924 INF program: Installed:
17:32:17,924 INF program: zsh-5.5.1-6.el8_1.2.x86_64
17:32:17,925 INF program: 
17:32:17,925 INF program: Complete!
17:32:17,925 DBG program: Return code: 0


I'm closing this bug, but feel free to re-open if you manage to reproduce it on RHEL-8.