From a71971e69eb4486a088e7759db4f66a33a87229d Mon Sep 17 00:00:00 2001 From: James Falcon Date: Fri, 24 Sep 2021 16:26:40 -0500 Subject: [PATCH 1/6] Wait for apt lock Currently any attempt to run an apt command while another process holds an apt lock will fail. We should instead wait to acquire the apt lock. LP: #1944611 --- cloudinit/distros/debian.py | 85 +++++++++++++++++++-- tests/unittests/test_distros/test_debian.py | 80 ++++++++++++++++++- 2 files changed, 156 insertions(+), 9 deletions(-) diff --git a/cloudinit/distros/debian.py b/cloudinit/distros/debian.py index f2b4dfc9970..d484a238dd3 100644 --- a/cloudinit/distros/debian.py +++ b/cloudinit/distros/debian.py @@ -7,8 +7,10 @@ # Author: Joshua Harlow # # This file is part of cloud-init. See LICENSE file for license information. - +import fcntl import os +import time +from contextlib import ExitStack from cloudinit import distros from cloudinit import helpers @@ -22,6 +24,7 @@ LOG = logging.getLogger(__name__) +APT_LOCK_WAIT_TIMEOUT = 30 APT_GET_COMMAND = ('apt-get', '--option=Dpkg::Options::=--force-confold', '--option=Dpkg::options::=--force-unsafe-io', '--assume-yes', '--quiet') @@ -41,6 +44,12 @@ NETWORK_CONF_FN = "/etc/network/interfaces.d/50-cloud-init" LOCALE_CONF_FN = "/etc/default/locale" +APT_LOCK_FILES = [ + '/var/lib/dpkg/lock', + '/var/lib/apt/lists/lock', + '/var/cache/apt/archives/lock', +] + class Distro(distros.Distro): hostname_conf_fn = "/etc/hostname" @@ -155,7 +164,72 @@ def _get_localhost_ip(self): def set_timezone(self, tz): distros.set_etc_timezone(tz=tz, tz_file=self._find_tz_file(tz)) + def _is_apt_lock_available(self, lock_files=None): + """Determines if another process holds any apt locks. + + If all locks are clear, return True else False. + """ + if lock_files is None: + lock_files = APT_LOCK_FILES + with ExitStack() as stack: + file_handles = [] + for lock in lock_files: + try: + file_handles.append(stack.enter_context(open(lock, 'w'))) + except FileNotFoundError: + # If the lock file doesn't even exist yet, then we don't + # have to wait for it + pass + for handle in file_handles: + try: + fcntl.lockf(handle, fcntl.LOCK_EX | fcntl.LOCK_NB) + except IOError: + return False + return True + + def _wait_for_apt_install( + self, short_cmd, subp_kwargs, timeout=APT_LOCK_WAIT_TIMEOUT + ): + """Wait for apt install to complete. + + short_cmd: Name of command like "upgrade" or "install" + subp_kwargs: kwargs to pass to subp + """ + start_time = time.time() + LOG.debug('Waiting for apt lock') + while time.time() - start_time < timeout: + if not self._is_apt_lock_available(): + time.sleep(1) + continue + LOG.debug('apt lock clear') + try: + # Allow the output of this to flow outwards (not be captured) + log_msg = "apt-%s [%s]" % ( + short_cmd, + ' '.join(subp_kwargs['args']) + ) + return util.log_time( + logfunc=LOG.debug, + msg=log_msg, + func=subp.subp, + kwargs=subp_kwargs, + ) + except subp.ProcessExecutionError as e: + if e.exit_code == 100 and 'Could not get lock' in e.stderr: + LOG.debug('Could not obtain apt lock') + time.sleep(1) + raise TimeoutError('Could not get apt lock') + def package_command(self, command, args=None, pkgs=None): + """Run the given package command. + + On Debian, this will run apt-get (unless APT_GET_COMMAND is set). + + command: The command to run, like "upgrade" or "install" + args: Arguments passed to apt itself in addition to + any specified in APT_GET_COMMAND + pkgs: Apt packages that the command will apply to + """ if pkgs is None: pkgs = [] @@ -185,11 +259,10 @@ def package_command(self, command, args=None, pkgs=None): pkglist = util.expand_package_list('%s=%s', pkgs) cmd.extend(pkglist) - # Allow the output of this to flow outwards (ie not be captured) - util.log_time(logfunc=LOG.debug, - msg="apt-%s [%s]" % (command, ' '.join(cmd)), - func=subp.subp, - args=(cmd,), kwargs={'env': e, 'capture': False}) + self._wait_for_apt_install( + short_cmd=command, + subp_kwargs={'args': cmd, 'env': e, 'capture': False} + ) def update_package_sources(self): self._runner.run("update-sources", self.package_command, diff --git a/tests/unittests/test_distros/test_debian.py b/tests/unittests/test_distros/test_debian.py index 7ff8240b4aa..c43c1661e34 100644 --- a/tests/unittests/test_distros/test_debian.py +++ b/tests/unittests/test_distros/test_debian.py @@ -1,8 +1,16 @@ # This file is part of cloud-init. See LICENSE file for license information. +from itertools import count +from unittest import mock -from cloudinit import distros -from cloudinit import util -from cloudinit.tests.helpers import (FilesystemMockingTestCase, mock) +import pytest + +from cloudinit import distros, util +from cloudinit.distros.debian import ( + APT_GET_COMMAND, + APT_GET_WRAPPER, +) +from cloudinit.tests.helpers import FilesystemMockingTestCase +from cloudinit import subp @mock.patch("cloudinit.distros.debian.subp.subp") @@ -98,3 +106,69 @@ def test_falseish_locale_raises_valueerror(self, m_subp): m_subp.assert_not_called() self.assertEqual( 'Failed to provide locale value.', str(ctext_m.exception)) + + +@mock.patch.dict('os.environ', {}, clear=True) +@mock.patch("cloudinit.distros.debian.subp.which", return_value=True) +@mock.patch("cloudinit.distros.debian.subp.subp") +class TestPackageCommand: + distro = distros.fetch("debian")("debian", {}, None) + + @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", + return_value=True) + def test_simple_command(self, m_apt_avail, m_subp, m_which): + self.distro.package_command('update') + apt_args = [APT_GET_WRAPPER['command']] + apt_args.extend(APT_GET_COMMAND) + apt_args.append('update') + expected_call = { + 'args': apt_args, + 'capture': False, + 'env': {'DEBIAN_FRONTEND': 'noninteractive'}, + } + assert m_subp.call_args == mock.call(**expected_call) + + @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", + side_effect=[False, False, True]) + @mock.patch("cloudinit.distros.debian.time.sleep") + def test_wait_for_lock(self, m_sleep, m_apt_avail, m_subp, m_which): + self.distro._wait_for_apt_install("stub", {"args": "stub2"}) + assert m_sleep.call_args_list == [mock.call(1), mock.call(1)] + assert m_subp.call_args_list == [mock.call(args='stub2')] + + @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", + return_value=False) + @mock.patch("cloudinit.distros.debian.time.sleep") + @mock.patch("cloudinit.distros.debian.time.time", side_effect=count()) + def test_lock_wait_timeout( + self, m_time, m_sleep, m_apt_avail, m_subp, m_which + ): + with pytest.raises(TimeoutError): + self.distro._wait_for_apt_install("stub", "stub2", timeout=5) + assert m_subp.call_args_list == [] + + @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", + return_value=True) + @mock.patch("cloudinit.distros.debian.time.sleep") + def test_lock_exception_wait(self, m_sleep, m_apt_avail, m_subp, m_which): + exception = subp.ProcessExecutionError( + exit_code=100, stderr="Could not get apt lock" + ) + m_subp.side_effect = [exception, exception, "return_thing"] + ret = self.distro._wait_for_apt_install("stub", {"args": "stub2"}) + assert ret == "return_thing" + + @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", + return_value=True) + @mock.patch("cloudinit.distros.debian.time.sleep") + @mock.patch("cloudinit.distros.debian.time.time", side_effect=count()) + def test_lock_exception_timeout( + self, m_time, m_sleep, m_apt_avail, m_subp, m_which + ): + m_subp.side_effect = subp.ProcessExecutionError( + exit_code=100, stderr="Could not get apt lock" + ) + with pytest.raises(TimeoutError): + self.distro._wait_for_apt_install( + "stub", {"args": "stub2"}, timeout=5 + ) From ca04f0601ca9c5f0c4ba74f28fa62304dbb7a761 Mon Sep 17 00:00:00 2001 From: James Falcon Date: Wed, 29 Sep 2021 19:45:22 -0500 Subject: [PATCH 2/6] comments --- cloudinit/distros/debian.py | 32 ++++++++++----------- tests/unittests/test_distros/test_debian.py | 8 +++--- 2 files changed, 19 insertions(+), 21 deletions(-) diff --git a/cloudinit/distros/debian.py b/cloudinit/distros/debian.py index d484a238dd3..1bf9fc613ce 100644 --- a/cloudinit/distros/debian.py +++ b/cloudinit/distros/debian.py @@ -10,7 +10,6 @@ import fcntl import os import time -from contextlib import ExitStack from cloudinit import distros from cloudinit import helpers @@ -171,23 +170,18 @@ def _is_apt_lock_available(self, lock_files=None): """ if lock_files is None: lock_files = APT_LOCK_FILES - with ExitStack() as stack: - file_handles = [] - for lock in lock_files: - try: - file_handles.append(stack.enter_context(open(lock, 'w'))) - except FileNotFoundError: - # If the lock file doesn't even exist yet, then we don't - # have to wait for it - pass - for handle in file_handles: + for lock in lock_files: + if not os.path.exists(lock): + # Only wait for lock files that already exist + continue + with open(lock, 'w') as handle: try: fcntl.lockf(handle, fcntl.LOCK_EX | fcntl.LOCK_NB) except IOError: return False return True - def _wait_for_apt_install( + def _wait_for_apt_command( self, short_cmd, subp_kwargs, timeout=APT_LOCK_WAIT_TIMEOUT ): """Wait for apt install to complete. @@ -201,7 +195,7 @@ def _wait_for_apt_install( if not self._is_apt_lock_available(): time.sleep(1) continue - LOG.debug('apt lock clear') + LOG.debug('apt lock available') try: # Allow the output of this to flow outwards (not be captured) log_msg = "apt-%s [%s]" % ( @@ -215,9 +209,13 @@ def _wait_for_apt_install( kwargs=subp_kwargs, ) except subp.ProcessExecutionError as e: - if e.exit_code == 100 and 'Could not get lock' in e.stderr: - LOG.debug('Could not obtain apt lock') - time.sleep(1) + if any([ + e.exit_code != 100, + 'Could not get apt lock' not in e.stderr, + ]): + raise e + LOG.debug('Could not obtain apt lock') + time.sleep(1) raise TimeoutError('Could not get apt lock') def package_command(self, command, args=None, pkgs=None): @@ -259,7 +257,7 @@ def package_command(self, command, args=None, pkgs=None): pkglist = util.expand_package_list('%s=%s', pkgs) cmd.extend(pkglist) - self._wait_for_apt_install( + self._wait_for_apt_command( short_cmd=command, subp_kwargs={'args': cmd, 'env': e, 'capture': False} ) diff --git a/tests/unittests/test_distros/test_debian.py b/tests/unittests/test_distros/test_debian.py index c43c1661e34..9e2dffb8a2f 100644 --- a/tests/unittests/test_distros/test_debian.py +++ b/tests/unittests/test_distros/test_debian.py @@ -132,7 +132,7 @@ def test_simple_command(self, m_apt_avail, m_subp, m_which): side_effect=[False, False, True]) @mock.patch("cloudinit.distros.debian.time.sleep") def test_wait_for_lock(self, m_sleep, m_apt_avail, m_subp, m_which): - self.distro._wait_for_apt_install("stub", {"args": "stub2"}) + self.distro._wait_for_apt_command("stub", {"args": "stub2"}) assert m_sleep.call_args_list == [mock.call(1), mock.call(1)] assert m_subp.call_args_list == [mock.call(args='stub2')] @@ -144,7 +144,7 @@ def test_lock_wait_timeout( self, m_time, m_sleep, m_apt_avail, m_subp, m_which ): with pytest.raises(TimeoutError): - self.distro._wait_for_apt_install("stub", "stub2", timeout=5) + self.distro._wait_for_apt_command("stub", "stub2", timeout=5) assert m_subp.call_args_list == [] @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", @@ -155,7 +155,7 @@ def test_lock_exception_wait(self, m_sleep, m_apt_avail, m_subp, m_which): exit_code=100, stderr="Could not get apt lock" ) m_subp.side_effect = [exception, exception, "return_thing"] - ret = self.distro._wait_for_apt_install("stub", {"args": "stub2"}) + ret = self.distro._wait_for_apt_command("stub", {"args": "stub2"}) assert ret == "return_thing" @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", @@ -169,6 +169,6 @@ def test_lock_exception_timeout( exit_code=100, stderr="Could not get apt lock" ) with pytest.raises(TimeoutError): - self.distro._wait_for_apt_install( + self.distro._wait_for_apt_command( "stub", {"args": "stub2"}, timeout=5 ) From 70065ff8d5b2795eb40afb62ef7127944c591650 Mon Sep 17 00:00:00 2001 From: James Falcon Date: Sat, 16 Oct 2021 21:06:08 -0500 Subject: [PATCH 3/6] Fix broken unit test --- tests/unittests/test_handler/test_handler_landscape.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/tests/unittests/test_handler/test_handler_landscape.py b/tests/unittests/test_handler/test_handler_landscape.py index 003339853cd..1cc73ea26b4 100644 --- a/tests/unittests/test_handler/test_handler_landscape.py +++ b/tests/unittests/test_handler/test_handler_landscape.py @@ -22,6 +22,10 @@ def setUp(self): self.conf = self.tmp_path('client.conf', self.new_root) self.default_file = self.tmp_path('default_landscape', self.new_root) self.patchUtils(self.new_root) + self.add_patch( + 'cloudinit.distros.ubuntu.Distro.install_packages', + 'm_install_packages' + ) def test_handler_skips_empty_landscape_cloudconfig(self): """Empty landscape cloud-config section does no work.""" From 7577ec2c84949af746dbe4b4dd37024af53fa250 Mon Sep 17 00:00:00 2001 From: James Falcon Date: Mon, 18 Oct 2021 11:36:42 -0500 Subject: [PATCH 4/6] IOError->OSError --- cloudinit/distros/debian.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cloudinit/distros/debian.py b/cloudinit/distros/debian.py index 1bf9fc613ce..e1a88a36ea1 100644 --- a/cloudinit/distros/debian.py +++ b/cloudinit/distros/debian.py @@ -177,7 +177,7 @@ def _is_apt_lock_available(self, lock_files=None): with open(lock, 'w') as handle: try: fcntl.lockf(handle, fcntl.LOCK_EX | fcntl.LOCK_NB) - except IOError: + except OSError: return False return True From d7ae74836eda184867e00876e4f67a1b198375fe Mon Sep 17 00:00:00 2001 From: James Falcon Date: Mon, 18 Oct 2021 15:28:47 -0500 Subject: [PATCH 5/6] yo dawg. I heard you liked apt locks... --- cloudinit/distros/debian.py | 21 ++++++++++++++------- 1 file changed, 14 insertions(+), 7 deletions(-) diff --git a/cloudinit/distros/debian.py b/cloudinit/distros/debian.py index e1a88a36ea1..e219741c1e0 100644 --- a/cloudinit/distros/debian.py +++ b/cloudinit/distros/debian.py @@ -163,7 +163,7 @@ def _get_localhost_ip(self): def set_timezone(self, tz): distros.set_etc_timezone(tz=tz, tz_file=self._find_tz_file(tz)) - def _is_apt_lock_available(self, lock_files=None): + def _apt_lock_available(self, lock_files=None): """Determines if another process holds any apt locks. If all locks are clear, return True else False. @@ -192,7 +192,7 @@ def _wait_for_apt_command( start_time = time.time() LOG.debug('Waiting for apt lock') while time.time() - start_time < timeout: - if not self._is_apt_lock_available(): + if not self._apt_lock_available(): time.sleep(1) continue LOG.debug('apt lock available') @@ -209,12 +209,19 @@ def _wait_for_apt_command( kwargs=subp_kwargs, ) except subp.ProcessExecutionError as e: - if any([ - e.exit_code != 100, - 'Could not get apt lock' not in e.stderr, - ]): + # Even though we have already waited for the apt lock to be + # available, it is possible that the lock was acquired by + # another process since the check. Since apt doesn't provide + # a meaningful error code to check and checking the error + # text is fragile and subject to internationalization, we + # can instead check the apt lock again. If the apt lock is + # still available, given the length of an average apt + # transaction, it is extremely unlikely that another process + # raced us when we tried to acquire it, so raise the apt + # error received. If the lock is unavailable, just keep waiting + if self._apt_lock_available(): raise e - LOG.debug('Could not obtain apt lock') + LOG.debug('Another process holds apt lock. Waiting...') time.sleep(1) raise TimeoutError('Could not get apt lock') From 879f04a10436c7075cd9829e122580d0d2828251 Mon Sep 17 00:00:00 2001 From: James Falcon Date: Mon, 18 Oct 2021 16:47:27 -0500 Subject: [PATCH 6/6] update tests --- cloudinit/distros/debian.py | 4 ++-- tests/unittests/test_distros/test_debian.py | 16 ++++++++-------- 2 files changed, 10 insertions(+), 10 deletions(-) diff --git a/cloudinit/distros/debian.py b/cloudinit/distros/debian.py index e219741c1e0..f390147005a 100644 --- a/cloudinit/distros/debian.py +++ b/cloudinit/distros/debian.py @@ -208,7 +208,7 @@ def _wait_for_apt_command( func=subp.subp, kwargs=subp_kwargs, ) - except subp.ProcessExecutionError as e: + except subp.ProcessExecutionError: # Even though we have already waited for the apt lock to be # available, it is possible that the lock was acquired by # another process since the check. Since apt doesn't provide @@ -220,7 +220,7 @@ def _wait_for_apt_command( # raced us when we tried to acquire it, so raise the apt # error received. If the lock is unavailable, just keep waiting if self._apt_lock_available(): - raise e + raise LOG.debug('Another process holds apt lock. Waiting...') time.sleep(1) raise TimeoutError('Could not get apt lock') diff --git a/tests/unittests/test_distros/test_debian.py b/tests/unittests/test_distros/test_debian.py index 9e2dffb8a2f..a88c26864fa 100644 --- a/tests/unittests/test_distros/test_debian.py +++ b/tests/unittests/test_distros/test_debian.py @@ -1,5 +1,5 @@ # This file is part of cloud-init. See LICENSE file for license information. -from itertools import count +from itertools import count, cycle from unittest import mock import pytest @@ -114,7 +114,7 @@ def test_falseish_locale_raises_valueerror(self, m_subp): class TestPackageCommand: distro = distros.fetch("debian")("debian", {}, None) - @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", + @mock.patch("cloudinit.distros.debian.Distro._apt_lock_available", return_value=True) def test_simple_command(self, m_apt_avail, m_subp, m_which): self.distro.package_command('update') @@ -128,7 +128,7 @@ def test_simple_command(self, m_apt_avail, m_subp, m_which): } assert m_subp.call_args == mock.call(**expected_call) - @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", + @mock.patch("cloudinit.distros.debian.Distro._apt_lock_available", side_effect=[False, False, True]) @mock.patch("cloudinit.distros.debian.time.sleep") def test_wait_for_lock(self, m_sleep, m_apt_avail, m_subp, m_which): @@ -136,7 +136,7 @@ def test_wait_for_lock(self, m_sleep, m_apt_avail, m_subp, m_which): assert m_sleep.call_args_list == [mock.call(1), mock.call(1)] assert m_subp.call_args_list == [mock.call(args='stub2')] - @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", + @mock.patch("cloudinit.distros.debian.Distro._apt_lock_available", return_value=False) @mock.patch("cloudinit.distros.debian.time.sleep") @mock.patch("cloudinit.distros.debian.time.time", side_effect=count()) @@ -147,8 +147,8 @@ def test_lock_wait_timeout( self.distro._wait_for_apt_command("stub", "stub2", timeout=5) assert m_subp.call_args_list == [] - @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", - return_value=True) + @mock.patch("cloudinit.distros.debian.Distro._apt_lock_available", + side_effect=cycle([True, False])) @mock.patch("cloudinit.distros.debian.time.sleep") def test_lock_exception_wait(self, m_sleep, m_apt_avail, m_subp, m_which): exception = subp.ProcessExecutionError( @@ -158,8 +158,8 @@ def test_lock_exception_wait(self, m_sleep, m_apt_avail, m_subp, m_which): ret = self.distro._wait_for_apt_command("stub", {"args": "stub2"}) assert ret == "return_thing" - @mock.patch("cloudinit.distros.debian.Distro._is_apt_lock_available", - return_value=True) + @mock.patch("cloudinit.distros.debian.Distro._apt_lock_available", + side_effect=cycle([True, False])) @mock.patch("cloudinit.distros.debian.time.sleep") @mock.patch("cloudinit.distros.debian.time.time", side_effect=count()) def test_lock_exception_timeout(