search

fgrehm / vagrant-cachier

Caffeine reducer
http://fgrehm.viewdocs.io/vagrant-cachier
MIT License
1.08k stars 111 forks source link

Yum Caching (with Puppet) fails on Windows #117

Closed tknerr closed 9 years ago

tknerr commented 10 years ago

I'm on Windows 7 (x64), using Vagrant 1.6.3 with vagrant-cachier 0.8.0 and getting weird errors during the puppet run:

OSError: [Errno 26] Text file busy: '/var/cache/yum/x86_64/6/base/repomdnrv_nVtmp.xml'
 at /etc/puppet/manifests/common/base/utils.pp:16
err: /Stage[main]/Common::Base::Utils/Package[rsync]/ensure: change from absent to latest failed: Could not update: Execution of '/usr/bin/yum -d 0 -e 0 -y install rsync' returned 1: 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 285, in user_main
    errcode = main(args)
  File "/usr/share/yum-cli/yummain.py", line 136, in main
    result, resultmsgs = base.doCommands()
  File "/usr/share/yum-cli/cli.py", line 434, in doCommands
    self._getTs(needTsRemove)
  File "/usr/lib/python2.6/site-packages/yum/depsolve.py", line 99, in _getTs
    self._getTsInfo(remove_only)
  File "/usr/lib/python2.6/site-packages/yum/depsolve.py", line 110, in _getTsInfo
    pkgSack = self.pkgSack
  File "/usr/lib/python2.6/site-packages/yum/__init__.py", line 887, in <lambda>
    pkgSack = property(fget=lambda self: self._getSacks(),
  File "/usr/lib/python2.6/site-packages/yum/__init__.py", line 669, in _getSacks
    self.repos.populateSack(which=repos)
  File "/usr/lib/python2.6/site-packages/yum/repos.py", line 308, in populateSack
    sack.populate(repo, mdtype, callback, cacheonly)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 165, in populate
    if self._check_db_version(repo, mydbtype):
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 223, in _check_db_version
    return repo._check_db_version(mdtype)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1256, in _check_db_version
    repoXML = self.repoXML
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1455, in <lambda>
    repoXML = property(fget=lambda self: self._getRepoXML(),
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1447, in _getRepoXML
    self._loadRepoXML(text=self)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1437, in _loadRepoXML
    return self._groupLoadRepoXML(text, self._mdpolicy2mdtypes())
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1412, in _groupLoadRepoXML
    if self._commonLoadRepoXML(text):
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1230, in _commonLoadRepoXML
    result = self._getFileRepoXML(local, text)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1016, in _getFileRepoXML
    misc.unlink_f(tfname)
  File "/usr/lib/python2.6/site-packages/yum/misc.py", line 910, in unlink_f
    os.unlink(filename)

My colleague running the same project on a Linux host does not have besaid errors.

Not having this isolated in a small reproducible test case yet, but any ideas so far already?

tknerr commented 10 years ago

sorry - accidentally closed the issue, hit the wrong button. monday morning... ;-)

fgrehm commented 10 years ago

Does it fail when you use the shell provisioner as well or only with puppet?

tknerr commented 10 years ago

Yep, could reproduce it with a shell provisioner.

This is my Vagrantfile:

Vagrant.configure("2") do |config|
  config.vm.box = "chef/centos-6.5"
  config.vm.provision :shell, inline: "sudo yum -d 0 -e 0 -y install rsync"
end

That's the output:

Y:\tmp\vagrant-cachier-centos-bug>vagrant up
Bringing machine 'default' up with 'virtualbox' provider...
==> default: Importing base box 'chef/centos-6.5'...
==> default: Matching MAC address for NAT networking...
==> default: Checking if box 'chef/centos-6.5' is up to date...
==> default: Setting the name of the VM: vagrant-cachier-centos-bug_default_1406614726777_62728
==> default: Clearing any previously set network interfaces...
==> default: Preparing network interfaces based on configuration...
    default: Adapter 1: nat
==> default: Forwarding ports...
    default: 22 => 2222 (adapter 1)
==> default: Booting VM...
==> default: Waiting for machine to boot. This may take a few minutes...
    default: SSH address: 127.0.0.1:2222
    default: SSH username: vagrant
    default: SSH auth method: private key
    default: Warning: Connection timeout. Retrying...
    default: Warning: Remote connection disconnect. Retrying...
==> default: Machine booted and ready!
==> default: Checking for guest additions in VM...
==> default: Mounting shared folders...
    default: /vagrant => Y:/tmp/vagrant-cachier-centos-bug
    default: /tmp/vagrant-cache => W:/home/.vagrant.d/cache/chef/centos-6.5
==> default: Configuring cache buckets...
==> default: Running provisioner: shell...
    default: Running: inline script
==> default: Traceback (most recent call last):
==> default:   File "/usr/bin/yum", line 29, in <module>
==> default:
==> default: yummain.user_main(sys.argv[1:], exit_code=True)
==> default:   File "/usr/share/yum-cli/yummain.py", line 285, in user_main
==> default:
==> default: errcode = main(args)
==> default:   File "/usr/share/yum-cli/yummain.py", line 136, in main
==> default:
==> default: result, resultmsgs = base.doCommands()
==> default:   File "/usr/share/yum-cli/cli.py", line 434, in doCommands
==> default:
==> default: self._getTs(needTsRemove)
==> default:   File "/usr/lib/python2.6/site-packages/yum/depsolve.py", line 99, in _getTs
==> default:
==> default: self._getTsInfo(remove_only)
==> default:   File "/usr/lib/python2.6/site-packages/yum/depsolve.py", line 110, in _getTsInfo
==> default:
==> default: pkgSack = self.pkgSack
==> default:   File "/usr/lib/python2.6/site-packages/yum/__init__.py", line 887, in <lambda>
==> default:
==> default: pkgSack = property(fget=lambda self: self._getSacks(),
==> default:   File "/usr/lib/python2.6/site-packages/yum/__init__.py", line 669, in _getSacks
==> default:     self.repos.populateSack(which=repos)
==> default:   File "/usr/lib/python2.6/site-packages/yum/repos.py", line 308, in populateSack
==> default:
==> default: sack.populate(repo, mdtype, callback, cacheonly)
==> default:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 165, in populate
==> default:     if self._check_db_version(repo, mydbtype):
==> default:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 223, in _check_db_version
==> default:     return repo._check_db_version(mdtype)
==> default:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1256, in _check_db_version
==> default:
==> default: repoXML = self.repoXML
==> default:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1455, in <lambda>
==> default:
==> default: repoXML = property(fget=lambda self: self._getRepoXML(),
==> default:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1447, in _getRepoXML
==> default:
==> default: self._loadRepoXML(text=self)
==> default:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1437, in _loadRepoXML
==> default:
==> default: return self._groupLoadRepoXML(text, self._mdpolicy2mdtypes())
==> default:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1412, in _groupLoadRepoXML
==> default:
==> default: if self._commonLoadRepoXML(text):
==> default:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1230, in _commonLoadRepoXML
==> default:
==> default: result = self._getFileRepoXML(local, text)
==> default:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1016, in _getFileRepoXML
==> default:
==> default: misc.unlink_f(tfname)
==> default:   File "/usr/lib/python2.6/site-packages/yum/misc.py", line 910, in unlink_f
==> default:
==> default: os.unlink(filename)
==> default: OSError
==> default: : [Errno 26] Text file busy: '/var/cache/yum/x86_64/6/base/repomd_Y0lbhtmp.xml'
The following SSH command responded with a non-zero exit status.
Vagrant assumes that this means the command failed!

chmod +x /tmp/vagrant-shell && /tmp/vagrant-shell

Stdout from the command:

Stderr from the command:

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 285, in user_main
    errcode = main(args)
  File "/usr/share/yum-cli/yummain.py", line 136, in main
    result, resultmsgs = base.doCommands()
  File "/usr/share/yum-cli/cli.py", line 434, in doCommands
    self._getTs(needTsRemove)
  File "/usr/lib/python2.6/site-packages/yum/depsolve.py", line 99, in _getTs
    self._getTsInfo(remove_only)
  File "/usr/lib/python2.6/site-packages/yum/depsolve.py", line 110, in _getTsInfo
    pkgSack = self.pkgSack
  File "/usr/lib/python2.6/site-packages/yum/__init__.py", line 887, in <lambda>
    pkgSack = property(fget=lambda self: self._getSacks(),
  File "/usr/lib/python2.6/site-packages/yum/__init__.py", line 669, in _getSacks
    self.repos.populateSack(which=repos)
  File "/usr/lib/python2.6/site-packages/yum/repos.py", line 308, in populateSack
    sack.populate(repo, mdtype, callback, cacheonly)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 165, in populate
    if self._check_db_version(repo, mydbtype):
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 223, in _check_db_version
    return repo._check_db_version(mdtype)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1256, in _check_db_version
    repoXML = self.repoXML
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1455, in <lambda>
    repoXML = property(fget=lambda self: self._getRepoXML(),
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1447, in _getRepoXML
    self._loadRepoXML(text=self)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1437, in _loadRepoXML
    return self._groupLoadRepoXML(text, self._mdpolicy2mdtypes())
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1412, in _groupLoadRepoXML
    if self._commonLoadRepoXML(text):
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1230, in _commonLoadRepoXML
    result = self._getFileRepoXML(local, text)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1016, in _getFileRepoXML
    misc.unlink_f(tfname)
  File "/usr/lib/python2.6/site-packages/yum/misc.py", line 910, in unlink_f
    os.unlink(filename)
OSError: [Errno 26] Text file busy: '/var/cache/yum/x86_64/6/base/repomd_Y0lbhtmp.xml'
tknerr commented 10 years ago

Verified that the above example (Vagrantfile with shell provisioner) works with a clean cache and the yum cache bucket disabled.

fgrehm commented 10 years ago

That sucks =/ We'll probably have to disable this bucket for windows hosts as well

Just to make sure, do you have any difference between your W and Y drives that could cause this issue? I just noticed the root dir and the cache dir are being mapped to different drives:

    default: /vagrant => Y:/tmp/vagrant-cachier-centos-bug
    default: /tmp/vagrant-cache => W:/home/.vagrant.d/cache/chef/centos-6.5
tknerr commented 10 years ago

Shouldn't make a difference, I was just cloning the repository on a different drive, but I will give it try and report back to you.

Strange though since caching apt (not apt-lists) and gems work without issues on windows...

tknerr commented 10 years ago

That is strange....

Tried

  1. with the cache and the repo being both on the W:\
  2. with the cache and the repo being mixed on Y:\ and W:\ drive

...but I could not reproduce it anymore.

Also tried variations with a clean cache and with a partially filled cache, everything works so far.

Let me do some more testing and if I can't reproduce lets close this file it as a "windows hickup" :-)

fgrehm commented 10 years ago

Well, lets just keep it open for a little while, I'll ping you again before cutting the 1.0.0 release next week just to double check how things are going ;-)

tknerr commented 10 years ago

Waaaahhhh gotcha!

The root cause was an internal repo that was not available. Here's a Vagrantfile to reproduce:

Vagrant.configure("2") do |config|
  config.vm.box = "chef/centos-6.5"
  config.vm.provision :shell, inline: <<-EOF
    sed -i 's/^mirrorlist/#mirrorlist/g' /etc/yum.repos.d/CentOS-Base.repo
    sed -i 's/^#baseurl=.*$/baseurl=http:\\/\\/ooops-does-not-exist.com\\/foo/g' /etc/yum.repos.d/CentOS-Base.repo
    yum -y install rsync
  EOF
end

It seems to make a difference (at least on Windows) whether vagrant-cachier (more specifically: it's yum bucket) is enabled or not.

With yum bucket enabled I get the stacktraces:

...
==> vm2: Running provisioner: shell...
    vm2: Running: inline script
==> vm2: Loaded plugins: fastestmirror
==> vm2: Loading mirror speeds from cached hostfile
==> vm2: http://ooops-does-not-exist.com/foo/repodata/repomd.xml: [Errno 14] PYCURL ERROR 6 - "Couldn't resolve host 'ooops-does-not-exist.com'"
==> vm2: Trying other mirror.
==> vm2: Traceback (most recent call last):
==> vm2:   File "/usr/bin/yum", line 29, in <module>
==> vm2:
==> vm2: yummain.user_main(sys.argv[1:], exit_code=True)
==> vm2:   File "/usr/share/yum-cli/yummain.py", line 285, in user_main
==> vm2:
==> vm2: errcode = main(args)
==> vm2:   File "/usr/share/yum-cli/yummain.py", line 136, in main
==> vm2:
==> vm2: result, resultmsgs = base.doCommands()
==> vm2:   File "/usr/share/yum-cli/cli.py", line 434, in doCommands
==> vm2:
==> vm2: self._getTs(needTsRemove)
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/depsolve.py", line 99, in _getTs
==> vm2:
==> vm2: self._getTsInfo(remove_only)
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/depsolve.py", line 110, in _getTsInfo
==> vm2:
==> vm2: pkgSack = self.pkgSack
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/__init__.py", line 887, in <lambda>
==> vm2:
==> vm2: pkgSack = property(fget=lambda self: self._getSacks(),
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/__init__.py", line 669, in _getSacks
==> vm2:
==> vm2: self.repos.populateSack(which=repos)
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/repos.py", line 308, in populateSack
==> vm2:
==> vm2: sack.populate(repo, mdtype, callback, cacheonly)
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 165, in populate
==> vm2:
==> vm2: if self._check_db_version(repo, mydbtype):
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 223, in _check_db_version
==> vm2:
==> vm2: return repo._check_db_version(mdtype)
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1256, in _check_db_version
==> vm2:
==> vm2: repoXML = self.repoXML
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1455, in <lambda>
==> vm2:
==> vm2: repoXML = property(fget=lambda self: self._getRepoXML(),
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1447, in _getRepoXML
==> vm2:
==> vm2: self._loadRepoXML(text=self)
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1437, in _loadRepoXML
==> vm2:
==> vm2: return self._groupLoadRepoXML(text, self._mdpolicy2mdtypes())
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1412, in _groupLoadRepoXML
==> vm2:
==> vm2: if self._commonLoadRepoXML(text):
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1230, in _commonLoadRepoXML
==> vm2:
==> vm2: result = self._getFileRepoXML(local, text)
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1016, in _getFileRepoXML
==> vm2:
==> vm2: misc.unlink_f(tfname)
==> vm2:   File "/usr/lib/python2.6/site-packages/yum/misc.py", line 910, in unlink_f
==> vm2:
==> vm2: os.unlink(filename)
==> vm2: OSError
==> vm2: :
==> vm2: [Errno 26] Text file busy: '/var/cache/yum/x86_64/6/base/repomdr_uuDatmp.xml'
The following SSH command responded with a non-zero exit status.
Vagrant assumes that this means the command failed!

chmod +x /tmp/vagrant-shell && /tmp/vagrant-shell

Stdout from the command:

Loaded plugins: fastestmirror
Loading mirror speeds from cached hostfile

Stderr from the command:

http://ooops-does-not-exist.com/foo/repodata/repomd.xml: [Errno 14] PYCURL ERROR 6 - "Couldn't resolve host 'ooops-does-not-exist.com'"
Trying other mirror.
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 285, in user_main
    errcode = main(args)
  File "/usr/share/yum-cli/yummain.py", line 136, in main
    result, resultmsgs = base.doCommands()
  File "/usr/share/yum-cli/cli.py", line 434, in doCommands
    self._getTs(needTsRemove)
  File "/usr/lib/python2.6/site-packages/yum/depsolve.py", line 99, in _getTs
    self._getTsInfo(remove_only)
  File "/usr/lib/python2.6/site-packages/yum/depsolve.py", line 110, in _getTsInfo
    pkgSack = self.pkgSack
  File "/usr/lib/python2.6/site-packages/yum/__init__.py", line 887, in <lambda>
    pkgSack = property(fget=lambda self: self._getSacks(),
  File "/usr/lib/python2.6/site-packages/yum/__init__.py", line 669, in _getSacks
    self.repos.populateSack(which=repos)
  File "/usr/lib/python2.6/site-packages/yum/repos.py", line 308, in populateSack
    sack.populate(repo, mdtype, callback, cacheonly)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 165, in populate
    if self._check_db_version(repo, mydbtype):
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 223, in _check_db_version
    return repo._check_db_version(mdtype)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1256, in _check_db_version
    repoXML = self.repoXML
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1455, in <lambda>
    repoXML = property(fget=lambda self: self._getRepoXML(),
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1447, in _getRepoXML
    self._loadRepoXML(text=self)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1437, in _loadRepoXML
    return self._groupLoadRepoXML(text, self._mdpolicy2mdtypes())
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1412, in _groupLoadRepoXML
    if self._commonLoadRepoXML(text):
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1230, in _commonLoadRepoXML
    result = self._getFileRepoXML(local, text)
  File "/usr/lib/python2.6/site-packages/yum/yumRepo.py", line 1016, in _getFileRepoXML
    misc.unlink_f(tfname)
  File "/usr/lib/python2.6/site-packages/yum/misc.py", line 910, in unlink_f
    os.unlink(filename)
OSError: [Errno 26] Text file busy: '/var/cache/yum/x86_64/6/base/repomdr_uuDatmp.xml'

With yum bucket disabled there are no stacktraces and the error is clearly recognizable:

...
==> vm2: Running provisioner: shell...
    vm2: Running: inline script
==> vm2: Loaded plugins: fastestmirror
==> vm2: Determining fastest mirrors
==> vm2: http://ooops-does-not-exist.com/foo/repodata/repomd.xml: [Errno 14] PYCURL ERROR 6 - "Couldn't resolve host 'ooops-does-not-exist.com'"
==> vm2: Trying other mirror.
==> vm2: Error: Cannot retrieve repository metadata (repomd.xml) for repository: base. Please verify its path and try again
The following SSH command responded with a non-zero exit status.
Vagrant assumes that this means the command failed!

chmod +x /tmp/vagrant-shell && /tmp/vagrant-shell

Stdout from the command:

Loaded plugins: fastestmirror
Determining fastest mirrors

Stderr from the command:

http://ooops-does-not-exist.com/foo/repodata/repomd.xml: [Errno 14] PYCURL ERROR 6 - "Couldn't resolve host 'ooops-does-not-exist.com'"
Trying other mirror.
Error: Cannot retrieve repository metadata (repomd.xml) for repository: base. Please verify its path and try again

It's not a dealbreaker, since everything works as expected again once the repo is available.

tknerr commented 10 years ago

@fgrehm feel free to close - this was an erroneous situation that should not happen. The additional stacktraces distracted from the original root cause, but that's all. The did not add further harm.

I'm :+1: for keeping the yum cache enabled on windows hosts, i.e. keeping everything as is and no fix necessary.

fgrehm commented 9 years ago

Glad you tracked it down. I'll keep this open tagged with documentation so that we remember to add some notes about it on our docs website.

Thanks for debugging! :-)