Install hook fails with "hook "install" (via explicit, bespoke hook script) failed: exit status 1" and zero useful output

[Michael Skalka]

As seen on this test run: https://solutions.qa.canonical.com/testruns/testRun/c71ae9d9-9ce5-4f3a-98de-1b33e29767b6
Crashdump here: https://oil-jenkins.canonical.com/artifacts/c71ae9d9-9ce5-4f3a-98de-1b33e29767b6/generated/generated/kubernetes/juju-crashdump-kubernetes-2021-02-18-23.21.51.tar.gz

The elasticsearch/2 unit fails on its install hook with an unhelpful error:

2021-02-18 23:19:53 WARNING juju-log Passing NO_PROXY string that includes a cidr. This may not be compatible with software you are running in your shell.
2021-02-18 23:20:12 WARNING install Traceback (most recent call last):
2021-02-18 23:20:12 WARNING install File "/var/lib/juju/agents/unit-elasticsearch-2/charm/hooks/install", line 215, in <module>
2021-02-18 23:20:12 WARNING install hooks.execute(sys.argv)
2021-02-18 23:20:12 WARNING install File "/var/lib/juju/agents/unit-elasticsearch-2/charm/hooks/charmhelpers/contrib/ansible/__init__.py", line 282, in execute
2021-02-18 23:20:12 WARNING install charmhelpers.contrib.ansible.apply_playbook(
2021-02-18 23:20:12 WARNING install File "/var/lib/juju/agents/unit-elasticsearch-2/charm/hooks/charmhelpers/contrib/ansible/__init__.py", line 216, in apply_playbook
2021-02-18 23:20:12 WARNING install subprocess.check_call(call, env=env)
2021-02-18 23:20:12 WARNING install File "/usr/lib/python3.8/subprocess.py", line 364, in check_call
2021-02-18 23:20:12 WARNING install raise CalledProcessError(retcode, cmd)
2021-02-18 23:20:12 WARNING install subprocess.CalledProcessError: Command '['ansible-playbook', '-c', 'local', 'playbook.yaml', '--tags', 'install']' returned non-zero exit status 2.
2021-02-18 23:20:12 ERROR juju.worker.uniter.operation runhook.go:136 hook "install" (via explicit, bespoke hook script) failed: exit status 1

And there are no logs created for the ansible playbook to indicate what went wrong, or any ansible logs at all. In order to effectively debug issues with this charm it needs to log these to somewhere.

[Jose Guedez (jfguedez)]

I was able to reproduce this issue. This seems to be a bug in charmhelpers, which uses check_call [0], but I think should use check_output, similar to the fix for LP#1928336 [1]. I filed a bug on the upstream project [2].

After patching the call to ansible to see the error, in my case I got the following (might not have been the same issue for this bug, impossible for me to say.

2021-06-21 03:05:31 WARNING install TASK [Install dependent packages.] *********************************************
2021-06-21 03:05:31 WARNING install failed: [localhost] (item=[u'openjdk-8-jre-headless', u'ufw']) => {"changed": false, "item": ["openjdk-8-jre-headless", "u
fw"], "msg": "Failed to update apt cache."}
2021-06-21 03:05:31 WARNING install to retry, use: --limit @/var/lib/juju/agents/unit-elasticsearch-0/charm/playbook.retry

So a failure to update the apt cache successfully. This happens because of the use of ES 5.x

# apt-get update
Ign:1 https://artifacts.elastic.co/packages/5.x/apt stable InRelease
Err:2 https://artifacts.elastic.co/packages/5.x/apt stable Release
  Could not handshake: The TLS connection was non-properly terminated. [IP: 10.0.0.1 3142]
Hit:3 http://archive.ubuntu.com/ubuntu bionic InRelease
Hit:4 http://archive.ubuntu.com/ubuntu bionic-updates InRelease
Get:5 http://security.ubuntu.com/ubuntu bionic-security InRelease [88.7 kB]
Hit:6 http://archive.ubuntu.com/ubuntu bionic-backports InRelease
Reading package lists... Done
E: The repository 'https://artifacts.elastic.co/packages/5.x/apt stable Release' does not have a Release file.
N: Updating from such a repository can't be done securely, and is therefore disabled by default.
N: See apt-secure(8) manpage for repository creation and user configuration details.

Updating the default to a more recent version is being tracked in LP#1895484 [3]

[0] https://github.com/juju/charm-helpers/blob/master/charmhelpers/contrib/ansible/__init__.py#L216
[1] https://bugs.launchpad.net/charm-juju-lint/+bug/1928336
[2] https://github.com/juju/charm-helpers/issues/612
[3] https://bugs.launchpad.net/charm-elasticsearch/+bug/1895484

[Jose Guedez (jfguedez)]

Actually this might just have happened due to proxy issues, or even the apt repository - https://github.com/elastic/elasticsearch/issues/20537

The lack of details about the error needs to be fixed regardless

[Xav Paice (xavpaice)]

2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 Traceback (most recent call last):
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 File "/var/lib/juju/agents/unit-elastic-0/charm/hooks/install", line 215, in <module>
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 hooks.execute(sys.argv)
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 File "/var/lib/juju/agents/unit-elastic-0/charm/hooks/charmhelpers/contrib/ansible/__init__.py", line 283, in execute
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 self.playbook_path, tags=[hook_name], extra_vars=extra_vars)
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 File "/var/lib/juju/agents/unit-elastic-0/charm/hooks/charmhelpers/contrib/ansible/__init__.py", line 198, in apply_playbook
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 allow_hyphens_in_keys=False, mode=(stat.S_IRUSR | stat.S_IWUSR))
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 File "/var/lib/juju/agents/unit-elastic-0/charm/hooks/charmhelpers/contrib/templating/contexts.py", line 106, in juju_state_to_yaml
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 'public-address'
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 File "/var/lib/juju/agents/unit-elastic-0/charm/hooks/charmhelpers/core/hookenv.py", line 92, in wrapper
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 res = func(*args, **kwargs)
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 File "/var/lib/juju/agents/unit-elastic-0/charm/hooks/charmhelpers/core/hookenv.py", line 869, in unit_get
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 return json.loads(subprocess.check_output(_args).decode('UTF-8'))
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 File "/usr/lib/python3.5/subprocess.py", line 626, in check_output
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 **kwargs).stdout
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 File "/usr/lib/python3.5/subprocess.py", line 708, in run
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.go:60 output=stdout, stderr=stderr)
2021-10-11 23:32:44 [ERROR] unit-elastic-0.log: 2021-10-11 23:32:39 WARNING unit.elastic/0.install logger.g...

[Eric Chen (eric-chen)]

This charm is no longer being actively maintained. Please consider using the new Canonical Observability Stack (https://charmhub.io/topics/canonical-observability-stack) or the opensearch-operator (https://github.com/canonical/opensearch-operator) instead.