hook error due to DPKG lock contention with unattended-upgr

[Frode Nordahl]

This might be a universal issue accross our charms, but filing to neutron-openvswitch as that is where it was observed.

While one might think this would be an edge case to rarely happen, we have recently seen it quite often in our gates:

https://openstack-ci-reports.ubuntu.com/artifacts/5c1/758738/5/check/focal-ussuri-ha/5c1663c/index.html
https://openstack-ci-reports.ubuntu.com/artifacts/9bc/759185/20/check/focal-ussuri-ha/9bcfdf0/index.html

2021-06-04 06:40:42 DEBUG juju.worker.uniter.remotestate watcher.go:512 got config change for neutron-openvswitch/1: ok=true, hashes=[2539623e557a33fe422cc6aa393bb6fcc4232681650b8dbae3eddfcf4f8537e1]
2021-06-04 06:40:42 DEBUG juju.worker.uniter resolver.go:170 no operations in progress; waiting for changes
2021-06-04 06:40:42 DEBUG juju.worker.uniter.operation executor.go:85 running operation run config-changed hook for neutron-openvswitch/1
2021-06-04 06:40:42 DEBUG juju.machinelock machinelock.go:162 acquire machine lock for neutron-openvswitch/1 uniter (run config-changed hook)
2021-06-04 06:40:42 DEBUG juju.machinelock machinelock.go:172 machine lock acquired for neutron-openvswitch/1 uniter (run config-changed hook)
2021-06-04 06:40:42 DEBUG juju.worker.uniter.operation executor.go:132 preparing operation "run config-changed hook" for neutron-openvswitch/1
2021-06-04 06:40:42 DEBUG juju.worker.uniter.operation executor.go:132 executing operation "run config-changed hook" for neutron-openvswitch/1
2021-06-04 06:40:42 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] executing: running config-changed hook
2021-06-04 06:40:42 DEBUG juju.worker.uniter.runner runner.go:705 starting jujuc server {unix @/var/lib/juju/agents/unit-neutron-openvswitch-1/agent.socket <nil>}
2021-06-04 06:40:43 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:43 WARNING juju-log Package openstack-release has no installation candidate.
2021-06-04 06:40:43 DEBUG jujuc server.go:211 running hook tool "config-get" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 DEBUG config-changed none
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "relation-ids" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "relation-list" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "relation-get" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 DEBUG config-changed none
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 INFO juju-log Registered config file: /etc/neutron/neutron.conf
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 INFO juju-log Registered config file: /etc/neutron/plugins/ml2/openvswitch_agent.ini
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 INFO juju-log Registered config file: /etc/default/openvswitch-switch
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 INFO juju-log Registered config file: /etc/neutron/l3_agent.ini
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 INFO juju-log Registered config file: /etc/neutron/fwaas_driver.ini
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 INFO juju-log Registered config file: /etc/neutron/metadata_agent.ini
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 INFO juju-log Registered config file: /etc/neutron/dhcp_agent.ini
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 INFO juju-log Registered config file: /etc/neutron/dnsmasq.conf
2021-06-04 06:40:44 DEBUG config-changed none
2021-06-04 06:40:44 DEBUG config-changed none
2021-06-04 06:40:44 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:44 WARNING juju-log Package openstack-release has no installation candidate.
2021-06-04 06:40:45 DEBUG config-changed none
2021-06-04 06:40:45 DEBUG config-changed none
2021-06-04 06:40:45 DEBUG config-changed none
2021-06-04 06:40:45 DEBUG config-changed none
2021-06-04 06:40:46 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:46 WARNING juju-log Package openstack-release has no installation candidate.
2021-06-04 06:40:47 DEBUG config-changed none
2021-06-04 06:40:47 DEBUG config-changed none
2021-06-04 06:40:47 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:47 WARNING juju-log Package openstack-release has no installation candidate.
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "relation-ids" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "relation-get" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "relation-list" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "relation-get" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "relation-ids" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "relation-ids" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "relation-ids" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "relation-get" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "relation-list" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "relation-get" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "relation-get" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 DEBUG config-changed none
2021-06-04 06:40:48 DEBUG config-changed none
2021-06-04 06:40:48 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:48 WARNING juju-log Package openstack-release has no installation candidate.
2021-06-04 06:40:49 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:49 INFO juju-log Making dir /var/lib/charm/neutron-openvswitch root:root 555
2021-06-04 06:40:49 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:49 INFO juju-log Making dir /etc/policy-rc.d root:root 555
2021-06-04 06:40:49 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:49 INFO juju-log Installing [] with options: ['--option=Dpkg::Options::=--force-confold']
2021-06-04 06:40:49 DEBUG config-changed Reading package lists...
2021-06-04 06:40:50 DEBUG config-changed Building dependency tree...
2021-06-04 06:40:50 DEBUG config-changed Reading state information...
2021-06-04 06:40:50 DEBUG config-changed 0 upgraded, 0 newly installed, 0 to remove and 40 not upgraded.
2021-06-04 06:40:50 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:50 WARNING juju-log Package openstack-release has no installation candidate.
2021-06-04 06:40:51 DEBUG config-changed Hit:1 http://nova.clouds.archive.ubuntu.com/ubuntu focal InRelease
2021-06-04 06:40:51 DEBUG config-changed Hit:2 http://nova.clouds.archive.ubuntu.com/ubuntu focal-updates InRelease
2021-06-04 06:40:51 DEBUG config-changed Hit:3 http://nova.clouds.archive.ubuntu.com/ubuntu focal-backports InRelease
2021-06-04 06:40:51 DEBUG config-changed Get:4 http://security.ubuntu.com/ubuntu focal-security InRelease [114 kB]
2021-06-04 06:40:52 DEBUG config-changed Fetched 114 kB in 1s (216 kB/s)
2021-06-04 06:40:53 DEBUG config-changed Reading package lists...
2021-06-04 06:40:53 DEBUG config-changed none
2021-06-04 06:40:53 DEBUG config-changed none
2021-06-04 06:40:53 DEBUG config-changed none
2021-06-04 06:40:54 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:54 WARNING juju-log Package openstack-release has no installation candidate.
2021-06-04 06:40:57 DEBUG jujuc server.go:211 running hook tool "status-set" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:57 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:57 INFO juju-log Installing ['libnetfilter-log1'] with options: ['--option=Dpkg::Options::=--force-confold']
2021-06-04 06:40:57 WARNING config-changed E: Could not get lock /var/lib/dpkg/lock-frontend. It is held by process 63435 (unattended-upgr)
2021-06-04 06:40:57 WARNING config-changed E: Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
2021-06-04 06:40:57 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:40:57 INFO juju-log Couldn't acquire DPKG lock. Will retry in 10 seconds
2021-06-04 06:41:07 WARNING config-changed E: Could not get lock /var/lib/dpkg/lock-frontend. It is held by process 63435 (unattended-upgr)
2021-06-04 06:41:07 WARNING config-changed E: Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
2021-06-04 06:41:07 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:41:07 INFO juju-log Couldn't acquire DPKG lock. Will retry in 10 seconds
2021-06-04 06:41:17 WARNING config-changed E: Could not get lock /var/lib/dpkg/lock-frontend. It is held by process 63435 (unattended-upgr)
2021-06-04 06:41:17 WARNING config-changed E: Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
2021-06-04 06:41:17 DEBUG jujuc server.go:211 running hook tool "juju-log" for neutron-openvswitch/1-config-changed-7328219406856007971
2021-06-04 06:41:17 INFO juju-log Couldn't acquire DPKG lock. Will retry in 10 seconds
2021-06-04 06:41:27 WARNING config-changed E: Could not get lock /var/lib/dpkg/lock-frontend. It is held by process 63435 (unattended-upgr)
2021-06-04 06:41:27 WARNING config-changed E: Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
2021-06-04 06:41:28 WARNING config-changed Traceback (most recent call last):
2021-06-04 06:41:28 WARNING config-changed File "/var/lib/juju/agents/unit-neutron-openvswitch-1/charm/hooks/config-changed", line 305, in <module>
2021-06-04 06:41:28 WARNING config-changed main()
2021-06-04 06:41:28 WARNING config-changed File "/var/lib/juju/agents/unit-neutron-openvswitch-1/charm/hooks/config-changed", line 298, in main
2021-06-04 06:41:28 WARNING config-changed hooks.execute(sys.argv)
2021-06-04 06:41:28 WARNING config-changed File "/var/lib/juju/agents/unit-neutron-openvswitch-1/charm/hooks/charmhelpers/core/hookenv.py", line 956, in execute
2021-06-04 06:41:28 WARNING config-changed self._hooks[hook_name]()
2021-06-04 06:41:28 WARNING config-changed File "/var/lib/juju/agents/unit-neutron-openvswitch-1/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1898, in wrapped_f
2021-06-04 06:41:28 WARNING config-changed return restart_on_change_helper(
2021-06-04 06:41:28 WARNING config-changed File "/var/lib/juju/agents/unit-neutron-openvswitch-1/charm/hooks/charmhelpers/core/host.py", line 837, in restart_on_change_helper
2021-06-04 06:41:28 WARNING config-changed r = lambda_f()
2021-06-04 06:41:28 WARNING config-changed File "/var/lib/juju/agents/unit-neutron-openvswitch-1/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1899, in <lambda>
2021-06-04 06:41:28 WARNING config-changed (lambda: f(*args, **kwargs)),
2021-06-04 06:41:28 WARNING config-changed File "/var/lib/juju/agents/unit-neutron-openvswitch-1/charm/hooks/config-changed", line 147, in config_changed
2021-06-04 06:41:28 WARNING config-changed install_packages()
2021-06-04 06:41:28 WARNING config-changed File "/var/lib/juju/agents/unit-neutron-openvswitch-1/charm/hooks/neutron_ovs_utils.py", line 278, in install_packages
2021-06-04 06:41:28 WARNING config-changed apt_install(missing_packages,
2021-06-04 06:41:28 WARNING config-changed File "/var/lib/juju/agents/unit-neutron-openvswitch-1/charm/hooks/charmhelpers/fetch/ubuntu.py", line 303, in apt_install
2021-06-04 06:41:28 WARNING config-changed _run_apt_command(cmd, fatal, quiet=quiet)
2021-06-04 06:41:28 WARNING config-changed File "/var/lib/juju/agents/unit-neutron-openvswitch-1/charm/hooks/charmhelpers/fetch/ubuntu.py", line 810, in _run_apt_command
2021-06-04 06:41:28 WARNING config-changed _run_with_retries(
2021-06-04 06:41:28 WARNING config-changed File "/var/lib/juju/agents/unit-neutron-openvswitch-1/charm/hooks/charmhelpers/fetch/ubuntu.py", line 787, in _run_with_retries
2021-06-04 06:41:28 WARNING config-changed result = subprocess.check_call(cmd, env=env, **kwargs)
2021-06-04 06:41:28 WARNING config-changed File "/usr/lib/python3.8/subprocess.py", line 364, in check_call
2021-06-04 06:41:28 WARNING config-changed raise CalledProcessError(retcode, cmd)
2021-06-04 06:41:28 WARNING config-changed subprocess.CalledProcessError: Command '['apt-get', '--assume-yes', '--option=Dpkg::Options::=--force-confold', 'install', 'libnetfilter-log1']' returned non-zero exit status 100.
2021-06-04 06:41:28 ERROR juju.worker.uniter.operation runhook.go:139 hook "config-changed" (via explicit, bespoke hook script) failed: exit status 1
2021-06-04 06:41:28 DEBUG juju.machinelock machinelock.go:186 machine lock released for neutron-openvswitch/1 uniter (run config-changed hook)
2021-06-04 06:41:28 DEBUG juju.worker.uniter.operation executor.go:115 lock released for neutron-openvswitch/1
2021-06-04 06:41:28 INFO juju.worker.uniter resolver.go:143 awaiting error resolution for "config-changed" hook
2021-06-04 06:41:28 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] error: hook failed: "config-changed"

[Alex Kavanagh (ajkavanagh)]

I think this is universal as it depends on the image that is being used for the charm/payload. i.e. unattended-upgrades being enabled. We could put some code in charm-helpers to detect this situation and wait for the u-u to complete and release the lock before we need to use the packaging system? U-u is generally a good thing (I guess), but we disable it in all of our OpenStack and series upgrade testing to ensure it doesn't interfere with the upgrades.