Skip to content
New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

#

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

Jump to bottom

hooks/install ran, but other hooks not expanded #310

Closed
stub42 opened this issue Jun 1, 2020 · 5 comments · Fixed by #312
Closed

hooks/install ran, but other hooks not expanded #310

stub42 opened this issue Jun 1, 2020 · 5 comments · Fixed by #312

Comments

@stub42
Copy link
Contributor

stub42 commented Jun 1, 2020

I have a charm using the Operator framework, working fine with Juju 2.7. It contains just hooks/install to bootstrap things:

root@ip-172-31-3-193:/var/lib/juju/agents/unit-plinth-0/charm/hooks# ls -la
total 8
drwxr-xr-x 2 root root 4096 Jun  1 10:31 .
drwxr-xr-x 9 root root 4096 Jun  1 10:33 ..
lrwxrwxrwx 1 root root   15 Jun  1 10:31 install -> ../src/charm.py

When deployed, logs show the install hook is called and by on_install handler invoked. However, as seen above no other hooks were created by the Operator framework. Juju ran the config-changed hook, but it of course did nothing.

2020-06-01 10:31:39 INFO juju.worker.uniter resolver.go:139 found queued "install" hook
020-06-01 10:31:39 DEBUG juju.worker.uniter.operation executor.go:83 running operation run install hook
2020-06-01 10:31:39 DEBUG juju.machinelock machinelock.go:162 acquire machine lock for uniter (run install hook)
2020-06-01 10:31:39 DEBUG juju.machinelock machinelock.go:172 machine lock acquired for uniter (run install hook)
2020-06-01 10:31:39 DEBUG juju.worker.uniter.operation executor.go:130 preparing operation "run install hook"
2020-06-01 10:31:39 DEBUG juju.worker.uniter.operation executor.go:130 executing operation "run install hook"
2020-06-01 10:31:39 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] executing: running install hook
2020-06-01 10:31:39 DEBUG juju.worker.uniter.runner runner.go:701 starting jujuc server  {unix @/var/lib/juju/agents/unit-plinth-0/agent.socket <nil>}
020-06-01 10:31:39 DEBUG install Reading package lists...
2020-06-01 10:31:39 DEBUG install Building dependency tree...
2020-06-01 10:31:39 DEBUG install Reading state information...
2020-06-01 10:31:39 DEBUG install python3-requests is already the newest version (2.22.0-2ubuntu1).
2020-06-01 10:31:39 DEBUG install python3-requests set to manually installed.
2020-06-01 10:31:39 DEBUG install python3-yaml is already the newest version (5.3.1-1).
2020-06-01 10:31:39 DEBUG install python3-yaml set to manually installed.
2020-06-01 10:31:39 DEBUG install The following additional packages will be installed:
2020-06-01 10:31:39 DEBUG install   libpq5
2020-06-01 10:31:39 DEBUG install Suggested packages:
2020-06-01 10:31:39 DEBUG install   python-psycopg2-doc
2020-06-01 10:31:39 DEBUG install The following NEW packages will be installed:
2020-06-01 10:31:39 DEBUG install   libpq5 python3-psycopg2
2020-06-01 10:31:40 DEBUG install 0 upgraded, 2 newly installed, 0 to remove and 0 not upgraded.
2020-06-01 10:31:40 DEBUG install Need to get 225 kB of archives.
2020-06-01 10:31:40 DEBUG install After this operation, 856 kB of additional disk space will be used.
2020-06-01 10:31:40 DEBUG install Get:1 http://ap-southeast-2.ec2.archive.ubuntu.com/ubuntu focal/main amd64 libpq5 amd64 12.2-4 [113 kB]
2020-06-01 10:31:40 DEBUG install Get:2 http://ap-southeast-2.ec2.archive.ubuntu.com/ubuntu focal/main amd64 python3-psycopg2 amd64 2.8.4-2 [112 kB]
2020-06-01 10:31:40 DEBUG install Fetched 225 kB in 0s (8645 kB/s)
2020-06-01 10:31:40 DEBUG install Selecting previously unselected package libpq5:amd64.
(Reading database ... 59708 files and directories currently installed.)
2020-06-01 10:31:40 DEBUG install Preparing to unpack .../libpq5_12.2-4_amd64.deb ...
2020-06-01 10:31:40 DEBUG install Unpacking libpq5:amd64 (12.2-4) ...
2020-06-01 10:31:40 DEBUG install Selecting previously unselected package python3-psycopg2.
2020-06-01 10:31:40 DEBUG install Preparing to unpack .../python3-psycopg2_2.8.4-2_amd64.deb ...
2020-06-01 10:31:40 DEBUG install Unpacking python3-psycopg2 (2.8.4-2) ...
2020-06-01 10:31:40 DEBUG install Setting up libpq5:amd64 (12.2-4) ...
2020-06-01 10:31:40 DEBUG install Setting up python3-psycopg2 (2.8.4-2) ...
2020-06-01 10:31:40 DEBUG install Processing triggers for libc-bin (2.31-0ubuntu9) ...
2020-06-01 10:31:42 DEBUG worker.uniter.jujuc server.go:209 running hook tool "juju-log"
2020-06-01 10:31:42 DEBUG juju-log Legacy hooks/install is just a link to ourselves.
2020-06-01 10:31:42 DEBUG worker.uniter.jujuc server.go:209 running hook tool "juju-log"
2020-06-01 10:31:42 DEBUG juju-log Emitting Juju event install.
[...]
2020-06-01 10:33:28 INFO juju.worker.uniter.operation runhook.go:142 ran "install" hook (via explicit, bespoke hook script)
2020-06-01 10:33:28 DEBUG juju.worker.uniter.operation executor.go:130 committing operation "run install hook"
2020-06-01 10:33:28 DEBUG juju.machinelock machinelock.go:186 machine lock released for uniter (run install hook)
2020-06-01 10:33:28 DEBUG juju.worker.uniter.operation executor.go:119 lock released
2020-06-01 10:33:28 INFO juju.worker.uniter.relation statetracker.go:153 joining relation "plinth:db postgresql:db"
2020-06-01 10:33:28 INFO juju.worker.uniter.relation statetracker.go:189 joined relation "plinth:db postgresql:db"
2020-06-01 10:33:28 DEBUG juju.worker.uniter.operation executor.go:83 running operation run relation-created (2; app: postgresql) hook
2020-06-01 10:33:28 DEBUG juju.machinelock machinelock.go:162 acquire machine lock for uniter (run relation-created (2; app: postgresql) hook)
2020-06-01 10:33:28 DEBUG juju.machinelock machinelock.go:172 machine lock acquired for uniter (run relation-created (2; app: postgresql) hook)
2020-06-01 10:33:28 DEBUG juju.worker.uniter.operation executor.go:130 preparing operation "run relation-created (2; app: postgresql) hook"
2020-06-01 10:33:28 DEBUG juju.worker.uniter.operation executor.go:130 executing operation "run relation-created (2; app: postgresql) hook"
2020-06-01 10:33:28 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] executing: running db-relation-created hook
2020-06-01 10:33:28 DEBUG juju.worker.uniter.runner runner.go:701 starting jujuc server  {unix @/var/lib/juju/agents/unit-plinth-0/agent.socket <nil>}
2020-06-01 10:33:28 INFO juju.worker.uniter.operation runhook.go:145 skipped "db-relation-created" hook (missing)
2020-06-01 10:33:28 DEBUG juju.worker.uniter.operation executor.go:130 committing operation "run relation-created (2; app: postgresql) hook"
2020-06-01 10:33:28 DEBUG juju.machinelock machinelock.go:186 machine lock released for uniter (run relation-created (2; app: postgresql) hook)
2020-06-01 10:33:28 DEBUG juju.worker.uniter.operation executor.go:119 lock released
2020-06-01 10:33:28 DEBUG juju.worker.uniter.operation executor.go:83 running operation accept leadership
2020-06-01 10:33:28 DEBUG juju.worker.uniter.operation executor.go:130 preparing operation "accept leadership"
2020-06-01 10:33:28 DEBUG juju.worker.uniter.operation executor.go:130 committing operation "accept leadership"
2020-06-01 10:33:29 INFO juju.worker.uniter resolver.go:139 found queued "leader-elected" hook
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:83 running operation run leader-elected hook
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:162 acquire machine lock for uniter (run leader-elected hook)
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:172 machine lock acquired for uniter (run leader-elected hook)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 preparing operation "run leader-elected hook"
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 executing operation "run leader-elected hook"
2020-06-01 10:33:29 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] executing: running leader-elected hook
2020-06-01 10:33:29 DEBUG juju.worker.uniter.runner runner.go:701 starting jujuc server  {unix @/var/lib/juju/agents/unit-plinth-0/agent.socket <nil>}
2020-06-01 10:33:29 INFO juju.worker.uniter.operation runhook.go:145 skipped "leader-elected" hook (missing)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 committing operation "run leader-elected hook"
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:186 machine lock released for uniter (run leader-elected hook)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:119 lock released
2020-06-01 10:33:29 DEBUG juju.worker.uniter resolver.go:162 no operations in progress; waiting for changes
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:83 running operation run config-changed hook
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:162 acquire machine lock for uniter (run config-changed hook)
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:172 machine lock acquired for uniter (run config-changed hook)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 preparing operation "run config-changed hook"
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 executing operation "run config-changed hook"
2020-06-01 10:33:29 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] executing: running config-changed hook
2020-06-01 10:33:29 DEBUG juju.worker.uniter.runner runner.go:701 starting jujuc server  {unix @/var/lib/juju/agents/unit-plinth-0/agent.socket <nil>}
2020-06-01 10:33:29 INFO juju.worker.uniter.operation runhook.go:145 skipped "config-changed" hook (missing)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 committing operation "run config-changed hook"
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:186 machine lock released for uniter (run config-changed hook)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:119 lock released
2020-06-01 10:33:29 INFO juju.worker.uniter resolver.go:139 found queued "start" hook
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:83 running operation run start hook
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:162 acquire machine lock for uniter (run start hook)
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:172 machine lock acquired for uniter (run start hook)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 preparing operation "run start hook"
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 executing operation "run start hook"
2020-06-01 10:33:29 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] executing: running start hook
2020-06-01 10:33:29 DEBUG juju.worker.uniter.runner runner.go:701 starting jujuc server  {unix @/var/lib/juju/agents/unit-plinth-0/agent.socket <nil>}
2020-06-01 10:33:29 INFO juju.worker.uniter.operation runhook.go:145 skipped "start" hook (missing)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 committing operation "run start hook"
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:186 machine lock released for uniter (run start hook)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:119 lock released
2020-06-01 10:33:29 DEBUG juju.worker.uniter resolver.go:162 no operations in progress; waiting for changes
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:83 running operation run relation-joined (2; unit: postgresql/0) hook
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:162 acquire machine lock for uniter (run relation-joined (2; unit: postgresql/0) hook)
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:172 machine lock acquired for uniter (run relation-joined (2; unit: postgresql/0) hook)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 preparing operation "run relation-joined (2; unit: postgresql/0) hook"
2020-06-01 10:33:29 DEBUG juju.worker.dependency engine.go:564 "metric-collect" manifold worker started at 2020-06-01 10:33:29.235946325 +0000 UTC
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 executing operation "run relation-joined (2; unit: postgresql/0) hook"
2020-06-01 10:33:29 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] executing: running db-relation-joined hook
2020-06-01 10:33:29 DEBUG juju.worker.uniter.runner runner.go:701 starting jujuc server  {unix @/var/lib/juju/agents/unit-plinth-0/agent.socket <nil>}
2020-06-01 10:33:29 INFO juju.worker.uniter.operation runhook.go:145 skipped "db-relation-joined" hook (missing)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 committing operation "run relation-joined (2; unit: postgresql/0) hook"
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:186 machine lock released for uniter (run relation-joined (2; unit: postgresql/0) hook)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:119 lock released
2020-06-01 10:33:29 DEBUG juju.worker.uniter resolver.go:162 no operations in progress; waiting for changes
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:83 running operation run relation-changed (2; unit: postgresql/0) hook
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:162 acquire machine lock for uniter (run relation-changed (2; unit: postgresql/0) hook)
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:172 machine lock acquired for uniter (run relation-changed (2; unit: postgresql/0) hook)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 preparing operation "run relation-changed (2; unit: postgresql/0) hook"
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 executing operation "run relation-changed (2; unit: postgresql/0) hook"
2020-06-01 10:33:29 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] executing: running db-relation-changed hook
2020-06-01 10:33:29 DEBUG juju.worker.uniter.runner runner.go:701 starting jujuc server  {unix @/var/lib/juju/agents/unit-plinth-0/agent.socket <nil>}
2020-06-01 10:33:29 INFO juju.worker.uniter.operation runhook.go:145 skipped "db-relation-changed" hook (missing)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:130 committing operation "run relation-changed (2; unit: postgresql/0) hook"
2020-06-01 10:33:29 DEBUG juju.machinelock machinelock.go:186 machine lock released for uniter (run relation-changed (2; unit: postgresql/0) hook)
2020-06-01 10:33:29 DEBUG juju.worker.uniter.operation executor.go:119 lock released
2020-06-01 10:33:29 DEBUG juju.worker.uniter resolver.go:162 no operations in progress; waiting for changes
2020-06-01 10:33:29 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] idle: 
2020-06-01 10:33:29 DEBUG juju.worker.uniter resolver.go:162 no operations in progress; waiting for changes
2020-06-01 10:34:17 DEBUG juju.worker.uniter.remotestate watcher.go:590 got a relation units change: {2 {map[postgresql/0:{1}] map[] []}}
2020-06-01 10:34:17 DEBUG juju.worker.uniter resolver.go:162 no operations in progress; waiting for changes
2020-06-01 10:34:17 DEBUG juju.worker.uniter.operation executor.go:83 running operation run relation-changed (2; unit: postgresql/0) hook
2020-06-01 10:34:17 DEBUG juju.machinelock machinelock.go:162 acquire machine lock for uniter (run relation-changed (2; unit: postgresql/0) hook)
2020-06-01 10:34:17 DEBUG juju.machinelock machinelock.go:172 machine lock acquired for uniter (run relation-changed (2; unit: postgresql/0) hook)
2020-06-01 10:34:17 DEBUG juju.worker.uniter.operation executor.go:130 preparing operation "run relation-changed (2; unit: postgresql/0) hook"
2020-06-01 10:34:17 DEBUG juju.worker.uniter.operation executor.go:130 executing operation "run relation-changed (2; unit: postgresql/0) hook"
2020-06-01 10:34:17 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] executing: running db-relation-changed hook
2020-06-01 10:34:17 DEBUG juju.worker.uniter.runner runner.go:701 starting jujuc server  {unix @/var/lib/juju/agents/unit-plinth-0/agent.socket <nil>}
2020-06-01 10:34:17 INFO juju.worker.uniter.operation runhook.go:145 skipped "db-relation-changed" hook (missing)
2020-06-01 10:34:17 DEBUG juju.worker.uniter.operation executor.go:130 committing operation "run relation-changed (2; unit: postgresql/0) hook"
2020-06-01 10:34:17 DEBUG juju.machinelock machinelock.go:186 machine lock released for uniter (run relation-changed (2; unit: postgresql/0) hook)
2020-06-01 10:34:17 DEBUG juju.worker.uniter.operation executor.go:119 lock released
2020-06-01 10:34:17 DEBUG juju.worker.uniter resolver.go:162 no operations in progress; waiting for changes
2020-06-01 10:34:17 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] idle:
@stub42
Copy link
Contributor Author

stub42 commented Jun 1, 2020

The charm was updated to Operator Framework 0.6.0 at the same time as changing the Juju version to 2.8.0rc3, which might be related to this issue.

@jameinel
Copy link
Member

jameinel commented Jun 1, 2020

I think this is just a bug in 0.6.0. We landed code to support "dispatch" but it was slightly incorrect.
Namely this line is relevant:

2020-06-01 10:31:42 DEBUG juju-log Legacy hooks/install is just a link to ourselves.

That means we think we are being invoked via 'dispatch' and looking to see if there is a hooks/* that needs to be executed. However, the check we are doing for it is:

if 'JUJU_DISPATCH_PATH' in os.environ:

Which in Juju 2.8 if you create 'hooks/install => ../src/charm.py', then JUJU_DISPATCH_PATH will be set, but we aren't being called from dispatch, so we need to create the other symlinks.

(the code that sets up the symlinks is in the call to:

        dispatcher.ensure_event_links(charm)

but that has:

        if self.is_dispatch_aware:
            # links aren't needed
            return

The issue is that 2.8 is dispatch aware, but was not invoked via dispatch.

@jameinel
Copy link
Member

jameinel commented Jun 1, 2020

On possible check we could do instead is

if 'hooks/' in self.argv[0]

Or another possibility is

if not (charmdir / 'dispatch').exists():

@jameinel
Copy link
Member

jameinel commented Jun 1, 2020

I think the trick is that we need both checks. "if dispatch exists but JUJU_DISPATCH_PATH" doesn't, then we need to create the symlinks (juju2.8 invoked via hooks/install). But if JUJU_DISPATCH_PATH isn't set and dispatch does exist we also need to create the symlinks (juju 2.7 with a charm that would like to use dispatch if possible.)

So

if self.is_dispatch_aware and (charmdir / 'dispatch').exists():
  return

chipaca added a commit to chipaca/operator that referenced this issue Jun 1, 2020
@chipaca
ops.main: only do _init_dispatch() if dispatch exists
f75ef55 
This avoids the situation where Juju is dispatch-aware but the charm
is not resulting in no symlinks getting created.

fixes: canonical#310
@chipaca chipaca mentioned this issue Jun 1, 2020
Merged
@chipaca
Copy link
Contributor

chipaca commented Jun 1, 2020

@jameinel I agree with your analysis, and I've implemented that change -- having first written failing tests for it :-)

chipaca added a commit that referenced this issue Jun 1, 2020
@chipaca
ops.main: only do _init_dispatch() if dispatch exists (#312)
4348872 
This avoids the situation where Juju is dispatch-aware but the charm
is not resulting in no symlinks getting created.

fixes: #310
# for free to join this conversation on GitHub. Already have an account? # to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

ops.main: only do _init_dispatch() if dispatch exists chipaca/operator
3 participants
@jameinel @chipaca @stub42