Hooks don't fire after upgrade 1.23.0

[Curtis Hovey]

This issue was separated from bug 1438489 because this is a new symptom probably related to other parts of the code:

Liam Young (gnuoy) wrote on 2015-04-17: #7
I've just upgraded from 1.22.1 to 1.23.0 (from proposed ppa) and after the upgrade I seem to have hit this bug.

Last entry in debug-log is:

unit-swift-proxy-0[8375]: 2015-04-17 10:20:02 ERROR juju.cmd supercommand.go:430 must restart: an agent upgrade is available
unit-swift-proxy-0[4189]: 2015-04-17 10:20:03 ERROR juju.worker.uniter.operation state.go:137 unexpected hook info with Kind Continue

juju set no longer fires hooks on the units.

I did not use upload-tools for the upgrade. I did:

juju set-env agent-metadata-url=https://streams.canonical.com/juju/tools
juju set-env agent-stream=proposed
juju upgrade-juju --version 1.23.0

[Curtis Hovey (sinzui)]

From https://bugs.launchpad.net/juju-core/+bug/1438489/comments/8
John Weldon (johnweldon4) wrote on 2015-04-17: #8
Even after the committed fix, hook operations don't fire any more after the upgrade. Investigating further.

[Curtis Hovey (sinzui)]

From https://bugs.launchpad.net/juju-core/+bug/1438489/comments/9

Martin Packman (gz) wrote 1 hour ago: #9
I can reproduce this with our standard upgrade job by adding a step at the end that sets a new value on our testing charm and expects it to propagate across a relation. It seems any juju deployment upgraded from 1.22 to 1.23 will basically be in an unusable state afterwards.

[Curtis Hovey (sinzui)]

The unit log from an example case looks like this:

2015-04-24 00:27:56 INFO juju.cmd supercommand.go:37 running jujud [1.23.1-trusty-amd64 gc]
2015-04-24 00:27:56 DEBUG juju.agent agent.go:418 read agent config, format "1.18"
2015-04-24 00:27:56 INFO juju.jujud unit.go:104 unit agent unit-apache2-0 start (1.23.1-trusty-amd64 [gc])
2015-04-24 00:27:56 INFO juju.network network.go:194 setting prefer-ipv6 to false
2015-04-24 00:27:56 INFO juju.worker runner.go:261 start "api"
2015-04-24 00:27:56 INFO juju.api apiclient.go:261 dialing "wss://10.12.29.108:17070/"
2015-04-24 00:27:56 INFO juju.api apiclient.go:183 connection established to "wss://10.12.29.108:17070/"
2015-04-24 00:27:57 INFO juju.worker runner.go:261 start "proxyupdater"
2015-04-24 00:27:57 DEBUG juju.worker.proxyupdater proxyupdater.go:68 write system files: false
2015-04-24 00:27:57 INFO juju.worker runner.go:261 start "upgrader"
2015-04-24 00:27:57 INFO juju.worker runner.go:261 start "logger"
2015-04-24 00:27:57 DEBUG juju.worker.logger logger.go:35 initial log config: "<root>=DEBUG"
2015-04-24 00:27:57 DEBUG juju.worker.logger logger.go:60 logger setup
2015-04-24 00:27:57 INFO juju.worker runner.go:261 start "uniter"
2015-04-24 00:27:57 INFO juju.worker runner.go:261 start "apiaddressupdater"
2015-04-24 00:27:57 INFO juju.worker runner.go:261 start "rsyslog"
2015-04-24 00:27:57 DEBUG juju.worker.rsyslog worker.go:93 starting rsyslog worker mode 1 for "unit-apache2-0" ""
2015-04-24 00:27:57 INFO juju.worker.leadership tracker.go:123 apache2/0 making initial claim for apache2 leadership
2015-04-24 00:27:57 INFO juju.worker.leadership tracker.go:165 checking apache2/0 for apache2 leadership
2015-04-24 00:27:57 DEBUG juju.worker.logger logger.go:45 reconfiguring logging from "<root>=DEBUG" to "<root>=WARNING;unit=DEBUG"
2015-04-24 00:27:58 ERROR juju.worker.uniter.operation state.go:137 unexpected hook info with Kind Continue

[Menno Finlay-Smits (menno.smits)]

For the record, here's some concise repro instructions:

juju122 bootstrap
juju122 deploy --repository $REPO local:trusty/dummy-source
# wait for unit to be deployed
juju122 set dummy-source token=foo
# observe in the unit logs that config-changed hook fires

juju123 upgrade-juju --upload-tools
# wait for the machines and unit to upgrade
juju123 set dummy-source token=bar
# observe in the unit logs that config-changed hook doesn't fire

where:
juju122 is the path to juju 1.22
juju123 is the path to juju 1.23
$REPO is a checkout of lp:juju-ci-tools/repository

I have confirmed that the problem isn't seen with a fresh Juju 1.23 environment, e.g.:

juju123 bootstrap
juju123 deploy --repository $REPO local:trusty/dummy-source
juju123 set dummy-source token=bar
# config-changed fires

[Menno Finlay-Smits (menno.smits)]

The issue is that the uniter is getting blocked when starting after the upgrade to 1.23. The call to WantLeaderSettingsEvents in Uniter.loop() doesn't return. This appears to be because the watcher returned by WatchLeadershipSettings isn't returning an event when there's no document for the service leader.

[Menno Finlay-Smits (menno.smits)]

initial fix here: https://github.com/mjs/juju/tree/1447846-hooks-dont-fire-after-upgrade-1.23

Needs tests.

[Menno Finlay-Smits (menno.smits)]

That branch now has an almost complete fix now (just needs update step idempotency test).

The fix also needs to be forward ported to master.

[Eric Snow (ericsnowcurrently)]

http://reviews.vapour.ws/r/1490/

[Eric Snow (ericsnowcurrently)]

FYI, the patch failed on the first attempt to merged (passed the second), due to a DB transaction issue. The failure resembles the one described in lp:1318366. It would be worth double-checking we didn't get something wrong in either the upgrade step or the tests.