charm install can fail due to configure_storage not being gated on install hook completion

[Tom Haddon]

We're seeing the following in CI:

....
2017-09-01 15:36:57 DEBUG metrics-filesystem-storage-attached Collecting pip
2017-09-01 15:36:57 DEBUG metrics-filesystem-storage-attached Building wheels for collected packages: pip
2017-09-01 15:36:57 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for pip: started
2017-09-01 15:36:58 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for pip: finished with status 'done'
2017-09-01 15:36:58 DEBUG metrics-filesystem-storage-attached Stored in directory: /root/.cache/pip/wheels/8f/99/55/2748f62b4bb1760281b0483d5eb27ee0a9397e317d15f3dbbe
2017-09-01 15:36:58 DEBUG metrics-filesystem-storage-attached Successfully built pip
2017-09-01 15:36:58 DEBUG metrics-filesystem-storage-attached Installing collected packages: pip
2017-09-01 15:36:58 DEBUG metrics-filesystem-storage-attached Found existing installation: pip 8.1.1
2017-09-01 15:36:58 DEBUG metrics-filesystem-storage-attached Not uninstalling pip at /usr/lib/python3/dist-packages, outside environment /usr
2017-09-01 15:36:59 DEBUG metrics-filesystem-storage-attached Successfully installed pip-8.1.2
2017-09-01 15:36:59 DEBUG metrics-filesystem-storage-attached Ignoring indexes: https://pypi.python.org/simple
2017-09-01 15:36:59 DEBUG metrics-filesystem-storage-attached Processing ./wheelhouse/Jinja2-2.9.6.tar.gz
2017-09-01 15:36:59 DEBUG metrics-filesystem-storage-attached Processing ./wheelhouse/PyYAML-3.12.tar.gz
2017-09-01 15:37:00 DEBUG metrics-filesystem-storage-attached Processing ./wheelhouse/MarkupSafe-1.0.tar.gz
2017-09-01 15:37:00 DEBUG metrics-filesystem-storage-attached Processing ./wheelhouse/pip-8.1.2.tar.gz
2017-09-01 15:37:00 DEBUG metrics-filesystem-storage-attached Processing ./wheelhouse/six-1.10.0.tar.gz
2017-09-01 15:37:00 DEBUG metrics-filesystem-storage-attached Processing ./wheelhouse/Tempita-0.5.2.tar.gz
2017-09-01 15:37:01 DEBUG metrics-filesystem-storage-attached Processing ./wheelhouse/charms.reactive-0.4.7.tar.gz
2017-09-01 15:37:01 DEBUG metrics-filesystem-storage-attached Processing ./wheelhouse/charmhelpers-0.17.0.tar.gz
2017-09-01 15:37:01 DEBUG metrics-filesystem-storage-attached Processing ./wheelhouse/netaddr-0.7.19.tar.gz
2017-09-01 15:37:02 DEBUG metrics-filesystem-storage-attached Processing ./wheelhouse/pyaml-16.12.2.tar.gz
2017-09-01 15:37:02 DEBUG metrics-filesystem-storage-attached Collecting MarkupSafe>=0.23 (from Jinja2==2.9.6)
2017-09-01 15:37:02 DEBUG metrics-filesystem-storage-attached Collecting pyaml (from charms.reactive==0.4.7)
2017-09-01 15:37:02 DEBUG metrics-filesystem-storage-attached Collecting charmhelpers>=0.5.0 (from charms.reactive==0.4.7)
2017-09-01 15:37:03 DEBUG metrics-filesystem-storage-attached Collecting netaddr (from charmhelpers==0.17.0)
2017-09-01 15:37:03 DEBUG metrics-filesystem-storage-attached Building wheels for collected packages: Jinja2, MarkupSafe, PyYAML, pip, six, Tempita, charms.reactive, pyaml, charmhelpers, netaddr
2017-09-01 15:37:03 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for Jinja2: started
2017-09-01 15:37:04 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for Jinja2: finished with status 'done'
2017-09-01 15:37:04 DEBUG metrics-filesystem-storage-attached Stored in directory: /root/.cache/pip/wheels/52/3d/13/4a245579846212c27bf7edec0079c05e2afaf1a29f14b30cfb
2017-09-01 15:37:04 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for MarkupSafe: started
2017-09-01 15:37:04 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for MarkupSafe: finished with status 'done'
2017-09-01 15:37:04 DEBUG metrics-filesystem-storage-attached Stored in directory: /root/.cache/pip/wheels/ad/d4/49/3e7561c91a648e8b017ea1d1b99fd6abb09ef44f8f563a7458
2017-09-01 15:37:04 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for PyYAML: started
2017-09-01 15:37:04 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for PyYAML: finished with status 'done'
2017-09-01 15:37:04 DEBUG metrics-filesystem-storage-attached Stored in directory: /root/.cache/pip/wheels/78/b9/7b/20138ca3b0c997b7aa8a66e7b0ca720d50553456901a79c427
2017-09-01 15:37:04 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for pip: started
2017-09-01 15:37:05 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for pip: finished with status 'done'
2017-09-01 15:37:05 DEBUG metrics-filesystem-storage-attached Stored in directory: /root/.cache/pip/wheels/8f/99/55/2748f62b4bb1760281b0483d5eb27ee0a9397e317d15f3dbbe
2017-09-01 15:37:05 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for six: started
2017-09-01 15:37:05 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for six: finished with status 'done'
2017-09-01 15:37:05 DEBUG metrics-filesystem-storage-attached Stored in directory: /root/.cache/pip/wheels/d4/36/51/4b796a3ac29bddbe7ed05bd57b8007b3e862447d708f8da8f9
2017-09-01 15:37:05 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for Tempita: started
2017-09-01 15:37:07 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for Tempita: finished with status 'done'
2017-09-01 15:37:07 DEBUG metrics-filesystem-storage-attached Stored in directory: /root/.cache/pip/wheels/5a/83/2c/0d61af6310bbb498e2ccc58d73f95f76115aebbecf413396e2
2017-09-01 15:37:07 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for charms.reactive: started
2017-09-01 15:37:07 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for charms.reactive: finished with status 'done'
2017-09-01 15:37:07 DEBUG metrics-filesystem-storage-attached Stored in directory: /root/.cache/pip/wheels/79/3a/7c/db2b7f13be86476eef2dffd7d26e26e3cd7fbd9ac6f100b4be
2017-09-01 15:37:07 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for pyaml: started
2017-09-01 15:37:07 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for pyaml: finished with status 'done'
2017-09-01 15:37:07 DEBUG metrics-filesystem-storage-attached Stored in directory: /root/.cache/pip/wheels/ad/fa/91/1ec75f40256a7ee08eaa20e58e8e6db4a63d4c44f073a5818f
2017-09-01 15:37:07 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for charmhelpers: started
2017-09-01 15:37:08 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for charmhelpers: finished with status 'done'
2017-09-01 15:37:08 DEBUG metrics-filesystem-storage-attached Stored in directory: /root/.cache/pip/wheels/50/42/e0/a303ee0cb37788cf2715adb6057b54f62d3cefbf702ebebe31
2017-09-01 15:37:08 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for netaddr: started
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Running setup.py bdist_wheel for netaddr: finished with status 'done'
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Stored in directory: /root/.cache/pip/wheels/35/dc/dd/8db94be2372798cea3a3c619b0a29bf8e428504a1731979adb
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Successfully built Jinja2 MarkupSafe PyYAML pip six Tempita charms.reactive pyaml charmhelpers netaddr
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Installing collected packages: MarkupSafe, Jinja2, PyYAML, pip, six, Tempita, pyaml, netaddr, charmhelpers, charms.reactive
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Found existing installation: MarkupSafe 0.23
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Uninstalling MarkupSafe-0.23:
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Successfully uninstalled MarkupSafe-0.23
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Found existing installation: Jinja2 2.8
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Uninstalling Jinja2-2.8:
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Successfully uninstalled Jinja2-2.8
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Found existing installation: PyYAML 3.11
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached DEPRECATION: Uninstalling a distutils installed project (PyYAML) has been deprecated and will be removed in a future version. This is due to the fact that uninstalling a distutils project will only partially uninstall the project.
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Uninstalling PyYAML-3.11:
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Successfully uninstalled PyYAML-3.11
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Found existing installation: pip 8.1.2
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Uninstalling pip-8.1.2:
2017-09-01 15:37:09 DEBUG metrics-filesystem-storage-attached Successfully uninstalled pip-8.1.2
2017-09-01 15:37:10 DEBUG metrics-filesystem-storage-attached Found existing installation: six 1.10.0
2017-09-01 15:37:10 DEBUG metrics-filesystem-storage-attached Uninstalling six-1.10.0:
2017-09-01 15:37:10 DEBUG metrics-filesystem-storage-attached Successfully uninstalled six-1.10.0
2017-09-01 15:37:10 DEBUG metrics-filesystem-storage-attached Successfully installed Jinja2-2.9.6 MarkupSafe-1.0 PyYAML-3.12 Tempita-0.5.2 charmhelpers-0.17.0 charms.reactive-0.4.7 netaddr-0.7.19 pip-8.1.2 pyaml-16.12.2 six-1.10.0
2017-09-01 15:37:11 INFO juju-log Reactive main running for hook metrics-filesystem-storage-attached
2017-09-01 15:37:11 INFO juju-log Initializing Snap Layer
2017-09-01 15:37:11 DEBUG metrics-filesystem-storage-attached none
2017-09-01 15:37:11 INFO juju-log Making dir /etc/systemd/system/snapd.service.d root:root 555
2017-09-01 15:37:11 INFO juju-log Writing file /etc/systemd/system/snapd.service.d/snap_layer_proxy.conf root:root 444
2017-09-01 15:37:13 INFO juju-log Invoking reactive handler: reactive/prometheus.py:141:configure_storage
2017-09-01 15:37:13 DEBUG juju-log No daemon args in config
2017-09-01 15:37:13 INFO juju-log Invoking reactive handler: reactive/prometheus.py:414:check_reconfig_prometheus
2017-09-01 15:37:13 DEBUG juju-log No daemon args in config
2017-09-01 15:37:13 INFO juju-log One of options affecting daemon args has changed, scheduling reconfiguration
2017-09-01 15:37:13 INFO juju-log CLI flags have change, scheduling reconfiguration
2017-09-01 15:37:13 INFO juju-log Daemon flags template changed, scheduling reconfiguration
2017-09-01 15:37:13 INFO juju-log Invoking reactive handler: reactive/prometheus.py:397:setup_prometheus
2017-09-01 15:37:13 INFO juju-log Invoking reactive handler: reactive/prometheus.py:285:write_prometheus_config_yml
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached Traceback (most recent call last):
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached File "/var/lib/juju/agents/unit-prometheus-0/charm/hooks/metrics-filesystem-storage-attached", line 19, in <module>
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached main()
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached File "/usr/local/lib/python3.5/dist-packages/charms/reactive/__init__.py", line 78, in main
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached bus.dispatch()
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached File "/usr/local/lib/python3.5/dist-packages/charms/reactive/bus.py", line 423, in dispatch
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached _invoke(other_handlers)
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached File "/usr/local/lib/python3.5/dist-packages/charms/reactive/bus.py", line 406, in _invoke
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached handler.invoke()
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached File "/usr/local/lib/python3.5/dist-packages/charms/reactive/bus.py", line 280, in invoke
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached self._action(*args)
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached File "/var/lib/juju/agents/unit-prometheus-0/charm/reactive/prometheus.py", line 290, in write_prometheus_config_yml
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached ver_major, ver_minor, ver_patch = get_version()
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached File "/var/lib/juju/agents/unit-prometheus-0/charm/reactive/prometheus.py", line 262, in get_version
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached output = subprocess.check_output([get_paths()['promtool'], 'version']).split(b'\n')[0]
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached File "/usr/lib/python3.5/subprocess.py", line 626, in check_output
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached **kwargs).stdout
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached File "/usr/lib/python3.5/subprocess.py", line 693, in run
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached with Popen(*popenargs, **kwargs) as process:
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached File "/usr/lib/python3.5/subprocess.py", line 947, in __init__
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached restore_signals, start_new_session)
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached File "/usr/lib/python3.5/subprocess.py", line 1551, in _execute_child
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached raise child_exception_type(errno_num, err_msg)
2017-09-01 15:37:13 DEBUG metrics-filesystem-storage-attached FileNotFoundError: [Errno 2] No such file or directory: '/snap/bin/prometheus.promtool'
2017-09-01 15:37:13 ERROR juju.worker.uniter.operation runhook.go:107 hook "metrics-filesystem-storage-attached" failed: exit status 1

This is because configure_storage is not gated on install hook completion.

[Jacek Nykis (jacekn)]

Storage hooks run before install so we will always hit this when using juju storage.

It is a bit tricky because we set "prometheus.do-install" state when "install" hooks is triggered but we also gate "check_reconfig_prometheus" on @when_not('prometheus.do-install')

So what I think is happening is that storage hooks run, set prometheus.do-check-reconfig state which then triggers check_reconfig_prometheus function _before_ install hook has time to set "prometheus.do-install".

I _think_ the fix is to simply remove "set_state('prometheus.do-check-reconfig')" from the "configure_storage()" function but please double check my logic.

[Stuart Bishop (stub)]

Recommended fix would be to not use the @hook('install') decorator, and instead use normal states.

Instead of:

@when('prometheus.do-install')
def install_packages():
   [...]
   reactive.remove_state('prometheus.do-install')

Have instead:

@when_not('prometheus.installed')
def install_packages():
    [...]
    reactive.set_state('prometheus.installed')

You can then remove the @hook('install') handler entirely, and the install_packages handler will run in the first hook (even if it is a storage hook).

[Jacek Nykis (jacekn)]

Yeah that works too. It's much more involved because it means rewriting reactive logic in quite a few places but we should benefit in the long term.