install hook error only gives useful information if Juju's logging-config="unit=DEBUG"

[Alvaro Uria]

Default Juju logging-config was "<root>=WARNING":
"""
2020-06-16 16:31:44 INFO juju.cmd.jujud agent.go:138 setting logging config to "<root>=WARNING"
2020-06-16 16:33:12 ERROR juju.worker.uniter.operation runhook.go:136 hook "install" (via explicit, bespoke hook script) failed: exit status 1
"""

As seen, that is the error given by the ceph-osd/1 unit.

After changing "juju model-config logging-config='<root>=WARNING; unit=DEBUG'":
"""
2020-06-17 08:36:46 DEBUG install E: dpkg was interrupted, you must manually run 'dpkg --configure -a' to correct the problem.
"""

A traceback is also returned, which seems fine just in DEBUG bug. However, I would have expected this one line to be part of the hookenv.ERROR logging level as it provides the exact issue and how it can be fixed.

[Alvaro Uria (aluria)]

This also happened on charm-nova-cloud-controller. See:
"""
2020-06-17 09:03:23 DEBUG cloud-compute-relation-changed dns.resolver.NoNameservers: All nameservers failed to answer the query vm4. IN A: Server 127.0.0.53 UDP port 53 answered SERVFAIL
2020-06-17 09:03:23 ERROR juju.worker.uniter.operation runhook.go:136 hook "cloud-compute-relation-changed" (via explicit, bespoke hook script) failed: exit status 1
"""

The ERROR level only says that the hook failed, while the DEBUG level says why (+ a python traceback).

[Alvaro Uria (aluria)]

In comment #1, problem is that the hostname "vm4" could not be resolved because /etc/resolv.conf did not have "search maas" to concatenate the domain ("vm4.maas").

[Alvaro Uria (aluria)]

1) Please find attached unit-ceph-osd-1.log.gz
* line 59-60 show:
"""
2020-06-16 16:31:44 INFO juju.cmd.jujud agent.go:138 setting logging config to "<root>=WARNING"
2020-06-16 16:33:12 ERROR juju.worker.uniter.operation runhook.go:136 hook "install" (via explicit, bespoke hook script) failed: exit status 1
"""

* line 230 and on show:
"""
2020-06-17 08:34:08 DEBUG juju.cmd supercommand.go:92 args: []string{"/var/lib/juju/tools/unit-ceph-osd-1/jujud", "unit", "--data-dir", "/var/lib/juju", "--unit-name", "ceph-osd/1", "--debug"}
2020-06-17 08:34:08 DEBUG juju.agent agent.go:575 read agent config, format "2.0"
2020-06-17 08:34:08 INFO juju.cmd.jujud agent.go:138 setting logging config to "<root>=WARNING"
2020-06-17 08:34:54 ERROR juju.worker.uniter.operation runhook.go:136 hook "install" (via explicit, bespoke hook script) failed: exit status 1
2020-06-17 08:36:36 DEBUG install E: dpkg was interrupted, you must manually run 'dpkg --configure -a' to correct the problem.
2020-06-17 08:36:36 INFO juju-log Couldn't acquire DPKG lock. Will retry in 10 seconds
2020-06-17 08:36:46 DEBUG install E: dpkg was interrupted, you must manually run 'dpkg --configure -a' to correct the problem.
2020-06-17 08:36:46 DEBUG install Traceback (most recent call last):
2020-06-17 08:36:46 DEBUG install File "/var/lib/juju/agents/unit-ceph-osd-1/charm/hooks/install.real", line 878, in <module>
2020-06-17 08:36:46 DEBUG install hooks.execute(sys.argv)
2020-06-17 08:36:46 DEBUG install File "/var/lib/juju/agents/unit-ceph-osd-1/charm/hooks/charmhelpers/core/hookenv.py", line 943, in execute
2020-06-17 08:36:46 DEBUG install self._hooks[hook_name]()
2020-06-17 08:36:46 DEBUG install File "/var/lib/juju/agents/unit-ceph-osd-1/charm/hooks/charmhelpers/contrib/hardening/harden.py", line 93, in _harden_inner2
2020-06-17 08:36:46 DEBUG install return f(*args, **kwargs)
2020-06-17 08:36:46 DEBUG install File "/var/lib/juju/agents/unit-ceph-osd-1/charm/hooks/install.real", line 317, in install
2020-06-17 08:36:46 DEBUG install apt_install(packages=ceph.determine_packages(), fatal=True)
2020-06-17 08:36:46 DEBUG install File "/var/lib/juju/agents/unit-ceph-osd-1/charm/hooks/charmhelpers/fetch/ubuntu.py", line 276, in apt_install
2020-06-17 08:36:46 DEBUG install _run_apt_command(cmd, fatal)
2020-06-17 08:36:46 DEBUG install File "/var/lib/juju/agents/unit-ceph-osd-1/charm/hooks/charmhelpers/fetch/ubuntu.py", line 768, in _run_apt_command
2020-06-17 08:36:46 DEBUG install _run_with_retries(
2020-06-17 08:36:46 DEBUG install File "/var/lib/juju/agents/unit-ceph-osd-1/charm/hooks/charmhelpers/fetch/ubuntu.py", line 748, in _run_with_retries
2020-06-17 08:36:46 DEBUG install result = subprocess.check_call(cmd, env=env)
2020-06-17 08:36:46 DEBUG install File "/usr/lib/python3.8/subprocess.py", line 364, in check_call
2020-06-17 08:36:46 DEBUG install raise CalledProcessError(retcode, cmd)
2020-06-17 08:36:46 DEBUG install subprocess.CalledProcessError: Command '['apt-get', '--assume-yes', '--option=Dpkg::Options::=--force-confold', 'install', 'ceph', 'gdisk', 'radosgw', 'xfsprogs', 'lvm2', 'parted', 'smartmontools', 'btrfs-progs']' r...

[Andreas Hasenack (ahasenack)]

I'm being bitten by this as well in the charmed-kubernetes bundle. All services are in an error state, and the juju unit logs only say:

unit-etcd-0: 22:15:29 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-etcd-1: 22:15:33 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-etcd-2: 22:15:36 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubeapi-load-balancer-0: 22:15:57 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubernetes-worker-1: 22:16:15 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubernetes-worker-2: 22:16:34 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubernetes-worker-0: 22:16:41 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubernetes-master-0: 22:16:42 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubernetes-master-1: 22:16:56 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-easyrsa-0: 22:20:46 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
ounit-etcd-0: 22:21:43 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-etcd-1: 22:21:47 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-etcd-2: 22:21:50 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubeapi-load-balancer-0: 22:22:11 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubernetes-worker-1: 22:22:29 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubernetes-worker-2: 22:22:48 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubernetes-worker-0: 22:22:55 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubernetes-master-0: 22:22:56 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1
unit-kubernetes-master-1: 22:23:10 ERROR juju.worker.uniter.operation hook "install" (via explicit, bespoke hook script) failed: exit status 1

That's not very useful.

[Thomas Dreibholz (dreibh)]

I see the same issue with Juju used for proxy charms with Open Source MANO Release EIGHT:
...
12 May 2021 18:15:08Z juju-unit executing running install hook
12 May 2021 18:15:14Z juju-unit error hook failed: "install"
12 May 2021 18:20:14Z workload maintenance installing charm software
12 May 2021 18:20:14Z juju-unit executing running install hook
12 May 2021 18:20:22Z juju-unit error hook failed: "install"
...

In this case, the errors are caused by Python PIP installation issues, but there is no useful log information written. The lack of useful log output is definitively an issue.

[Canonical Juju QA Bot (juju-qa-bot)]

This Medium-priority bug has not been updated in 60 days, so we're marking it Low importance. If you believe this is incorrect, please update the importance.