juju-core

Unit in "agent-state: error" cannot be resolved

Bug #1270041 reported by Ryan Finnie on 2014-01-17

This bug affects 13 people

Affects		Status	Importance	Assigned to	Milestone
	juju-core	Fix Released	Medium	Unassigned

Bug Description

I have a unit which is in "agent-state: error":

$ juju status
services:
  charmname:
    units:
      charmname/0:
        agent-state: started
        agent-version: 1.14.1.1
        machine: "2"
      charmname/1:
        agent-state: error
        agent-state-info: 'hook failed: "upgrade-charm"'
        agent-version: 1.14.1.1
        machine: "15"

but cannot be resolved:
$ juju resolved --retry charmname/1
error: cannot set resolved mode for unit "charmname/1": already resolved

The symptoms sound similar to LP: #1175031, but in a much newer version. Through a combination of "juju upgrade-charm --force charmname", "juju resolved charmname/1" and restarting the charm agent on the unit, I've been occasionally able to get it to retry, but no matter the outcome of the hooks, it doesn't clear the error state.

=== Agent start example ===

2014-01-16 20:50:27 INFO juju.jujud unit.go:72 unit agent unit-charmname-1 start
2014-01-16 20:50:27 INFO juju runner.go:253 worker: start "state"
2014-01-16 20:50:27 INFO juju.state open.go:68 opening state; mongo addresses: ["10.33.17.73:37017"]; entity "unit-charmname-1"
2014-01-16 20:50:27 INFO juju runner.go:253 worker: start "api"
2014-01-16 20:50:27 INFO juju apiclient.go:106 state/api: dialing "wss://10.33.17.73:17070/"
2014-01-16 20:50:27 INFO juju apiclient.go:116 state/api: connection established
2014-01-16 20:50:27 INFO juju.state open.go:106 connection established
2014-01-16 20:50:28 INFO juju runner.go:253 worker: start "upgrader"
2014-01-16 20:50:28 INFO juju runner.go:253 worker: start "uniter"
2014-01-16 20:50:28 INFO juju.worker.uniter uniter.go:83 unit "charmname/1" started
2014-01-16 20:50:28 INFO juju.worker.upgrader upgrader.go:139 desired tool version: 1.14.1.1
2014-01-16 20:50:28 INFO juju.worker.uniter modes.go:408 ModeInit starting
2014-01-16 20:50:28 INFO juju.worker.uniter modes.go:29 updating unit addresses
2014-01-16 20:50:28 DEBUG juju.worker.uniter.filter filter.go:472 charm check skipped, not yet installed.
2014-01-16 20:50:28 DEBUG juju.worker.uniter.filter filter.go:289 got unit change
2014-01-16 20:50:28 DEBUG juju.worker.uniter.filter filter.go:313 got relations change
2014-01-16 20:50:28 DEBUG juju.worker.uniter.filter filter.go:297 got service change
2014-01-16 20:50:28 DEBUG juju.worker.uniter.filter filter.go:478 preparing new upgrade event
2014-01-16 20:50:28 DEBUG juju.worker.uniter.filter filter.go:305 got config change
2014-01-16 20:50:28 DEBUG juju.worker.uniter.filter filter.go:309 preparing new config event
2014-01-16 20:50:28 INFO juju.worker.uniter modes.go:52 reconciling relation state
2014-01-16 20:50:28 INFO juju.worker.uniter uniter.go:508 joining relation "subcharm:a charmname:a"
2014-01-16 20:50:28 INFO juju.worker.uniter uniter.go:530 joined relation "subcharm:a charmname:a"
2014-01-16 20:50:28 DEBUG juju.worker.uniter modes.go:410 ModeInit exiting
2014-01-16 20:50:28 INFO juju.worker.uniter modes.go:408 ModeContinue starting
2014-01-16 20:50:28 INFO juju.worker.uniter modes.go:65 loading uniter state
2014-01-16 20:50:28 INFO juju.worker.uniter modes.go:109 awaiting error resolution for "upgrade-charm" hook
2014-01-16 20:50:28 DEBUG juju.worker.uniter modes.go:410 ModeContinue exiting
2014-01-16 20:50:28 INFO juju.worker.uniter modes.go:408 ModeHookError starting
2014-01-16 20:50:28 DEBUG juju.worker.uniter.filter filter.go:388 want resolved event
2014-01-16 20:50:28 DEBUG juju.worker.uniter.filter filter.go:382 want forced upgrade true
2014-01-16 20:50:28 DEBUG juju.worker.uniter.filter filter.go:486 no new charm event
2014-01-16 20:50:28 DEBUG juju.worker.uniter.filter filter.go:335 sent resolved event

=== Agent start example w/ upgrade-charm retry ===

2014-01-16 20:30:38 INFO juju.jujud unit.go:72 unit agent unit-charmname-1 start
2014-01-16 20:30:38 INFO juju runner.go:253 worker: start "state"
2014-01-16 20:30:38 INFO juju.state open.go:68 opening state; mongo addresses: ["10.33.17.73:37017"]; entity "unit-charmname-1"
2014-01-16 20:30:38 INFO juju runner.go:253 worker: start "api"
2014-01-16 20:30:38 INFO juju apiclient.go:106 state/api: dialing "wss://10.33.17.73:17070/"
2014-01-16 20:30:38 INFO juju apiclient.go:116 state/api: connection established
2014-01-16 20:30:38 INFO juju.state open.go:106 connection established
2014-01-16 20:30:39 INFO juju runner.go:253 worker: start "uniter"
2014-01-16 20:30:39 INFO juju.worker.uniter uniter.go:83 unit "charmname/1" started
2014-01-16 20:30:39 INFO juju.worker.uniter modes.go:408 ModeInit starting
2014-01-16 20:30:39 INFO juju.worker.uniter modes.go:29 updating unit addresses
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:472 charm check skipped, not yet installed.
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:289 got unit change
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:297 got service change
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:478 preparing new upgrade event
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:313 got relations change
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:305 got config change
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:309 preparing new config event
2014-01-16 20:30:39 INFO juju runner.go:253 worker: start "upgrader"
2014-01-16 20:30:39 INFO juju.worker.upgrader upgrader.go:139 desired tool version: 1.14.1.1
2014-01-16 20:30:39 INFO juju.worker.uniter modes.go:52 reconciling relation state
2014-01-16 20:30:39 INFO juju.worker.uniter uniter.go:508 joining relation "subcharm:a charmname:a"
2014-01-16 20:30:39 INFO juju.worker.uniter uniter.go:530 joined relation "subcharm:a charmname:a"
2014-01-16 20:30:39 DEBUG juju.worker.uniter modes.go:410 ModeInit exiting
2014-01-16 20:30:39 INFO juju.worker.uniter modes.go:408 ModeContinue starting
2014-01-16 20:30:39 INFO juju.worker.uniter modes.go:65 loading uniter state
2014-01-16 20:30:39 INFO juju.worker.uniter modes.go:109 awaiting error resolution for "upgrade-charm" hook
2014-01-16 20:30:39 DEBUG juju.worker.uniter modes.go:410 ModeContinue exiting
2014-01-16 20:30:39 INFO juju.worker.uniter modes.go:408 ModeHookError starting
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:388 want resolved event
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:382 want forced upgrade true
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:478 preparing new upgrade event
2014-01-16 20:30:39 DEBUG juju.worker.uniter modes.go:410 ModeHookError exiting
2014-01-16 20:30:39 INFO juju.worker.uniter modes.go:408 ModeUpgrading local:precise/charmname-155082009 starting
2014-01-16 20:30:39 INFO juju.worker.uniter uniter.go:230 fetching charm "local:precise/charmname-155082009"
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:332 sent upgrade event
2014-01-16 20:30:39 INFO juju charm.go:56 worker/uniter/charm: downloading local:precise/charmname-155082009 from http://kelpie.internal:8080/v1/AUTH_xxx/juju-env/local_3a_precise_2f_charmname-155082009
2014-01-16 20:30:39 INFO juju charm.go:68 worker/uniter/charm: download complete
2014-01-16 20:30:39 INFO juju charm.go:80 worker/uniter/charm: download verified
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:347 changing charm to "local:precise/charmname-155082009"
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:486 no new charm event
2014-01-16 20:30:39 INFO juju.worker.uniter uniter.go:253 deploying charm "local:precise/charmname-155082009"
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:305 got config change
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:309 preparing new config event
2014-01-16 20:30:39 DEBUG juju.worker.uniter.filter filter.go:313 got relations change
2014-01-16 20:30:39 INFO juju deployer.go:144 worker/uniter/charm: preparing charm upgrade
2014-01-16 20:30:39 INFO juju deployer.go:164 worker/uniter/charm: deploying charm
2014-01-16 20:30:40 INFO juju deployer.go:98 worker/uniter/charm: charm deployment succeeded
2014-01-16 20:30:40 INFO juju.worker.uniter uniter.go:264 charm "local:precise/charmname-155082009" is deployed
2014-01-16 20:30:40 DEBUG juju.worker.uniter modes.go:410 ModeUpgrading local:precise/charmname-155082009 exiting
2014-01-16 20:30:40 INFO juju.worker.uniter modes.go:408 ModeContinue starting
2014-01-16 20:30:40 INFO juju.worker.uniter modes.go:109 awaiting error resolution for "upgrade-charm" hook
2014-01-16 20:30:40 DEBUG juju.worker.uniter modes.go:410 ModeContinue exiting
2014-01-16 20:30:40 INFO juju.worker.uniter modes.go:408 ModeHookError starting
2014-01-16 20:30:40 DEBUG juju.worker.uniter.filter filter.go:388 want resolved event
2014-01-16 20:30:40 DEBUG juju.worker.uniter.filter filter.go:382 want forced upgrade true
2014-01-16 20:30:40 DEBUG juju.worker.uniter.filter filter.go:486 no new charm event
2014-01-16 20:30:40 DEBUG juju.worker.uniter.filter filter.go:335 sent resolved event
2014-01-16 20:30:43 DEBUG juju.worker.uniter.filter filter.go:289 got unit change

Tags:

Curtis Hovey (sinzui) on 2014-01-17

tags:	added: resolved
tags:	added: 1.14.1

Curtis Hovey (sinzui) on 2014-01-17

Changed in juju-core:
status:	New → Triaged
importance:	Undecided → High
tags:	added: upgrade-charm

Curtis Hovey (sinzui) on 2014-10-28

Changed in juju-core:
importance:	High → Medium

Revision history for this message

Peter Sabaini (peter-sabaini) wrote on 2015-02-05:

Download full text (19.7 KiB)

I have a similar issue:

$ juju status rabbitmq-server/1 | grep -A 3 rabbitmq-server/1:
      rabbitmq-server/1:
        agent-state: error
        agent-state-info: 'hook failed: "config-changed"'
        agent-version: 1.20.9.1

$ juju resolved rabbitmq-server/1
ERROR cannot set resolved mode for unit "rabbitmq-server/1": already resolved

When restarting jujud I can see it retrying the config-changed hook w/o issue, but the error state remains:

# restart jujud-unit-rabbitmq-server-1

-- log excerpt of unit-rabbitmq-server-1

I have a similar issue:

$ juju resolved rabbitmq-server/1
ERROR cannot set resolved mode for unit "rabbitmq-server/1": already resolved

When restarting jujud I can see it retrying the config-changed hook w/o issue, but the error state remains:

# restart jujud-unit-rabbitmq-server-1

-- log excerpt of unit-rabbitmq-server-1

2015-02-05 13:42:42 INFO juju.worker.uniter uniter.go:115 unit "rabbitmq-server/1" started
2015-02-05 13:42:42 DEBUG juju.worker.uniter runlistener.go:84 juju-run listener running
2015-02-05 13:42:42 INFO juju.worker.uniter modes.go:396 ModeContinue starting
2015-02-05 13:42:42 INFO juju.worker.uniter modes.go:31 loading uniter state
2015-02-05 13:42:42 INFO juju.worker.uniter modes.go:48 continuing after "config-changed" hook
2015-02-05 13:42:42 DEBUG juju.worker.uniter modes.go:398 ModeContinue exiting
2015-02-05 13:42:42 INFO juju.worker.uniter modes.go:396 ModeConfigChanged starting
2015-02-05 13:42:42 DEBUG juju.worker.uniter uniter.go:757 new environment change
2015-02-05 13:42:42 DEBUG juju.worker.uniter.filter filter.go:507 charm check skipped, not yet installed.
2015-02-05 13:42:42 DEBUG juju.worker.uniter.filter filter.go:325 got service change
2015-02-05 13:42:42 DEBUG juju.worker.uniter.filter filter.go:521 no new charm event
2015-02-05 13:42:42 DEBUG juju.worker.uniter.filter filter.go:317 got unit change
2015-02-05 13:42:42 DEBUG juju.worker.uniter.filter filter.go:341 got relations change
2015-02-05 13:42:42 DEBUG juju.worker.uniter.filter filter.go:333 got config change
2015-02-05 13:42:42 DEBUG juju.worker.uniter.filter filter.go:337 preparing new config event
2015-02-05 13:42:42 DEBUG juju.worker.uniter.filter filter.go:440 discarded config event
2015-02-05 13:42:42 INFO juju.worker.uniter uniter.go:480 running "config-changed" hook
2015-02-05 13:42:43 INFO worker.uniter.jujuc server.go:102 running hook tool "config-get" ["source" "--format=json"]
2015-02-05 13:42:43 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:43 INFO worker.uniter.jujuc server.go:102 running hook tool "config-get" ["key" "--format=json"]
2015-02-05 13:42:43 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:43 INFO worker.uniter.jujuc server.go:102 running hook tool "juju-log" ["Source is not present. Skipping"]
2015-02-05 13:42:43 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:43 INFO juju-log Source is not present. Skipping
2015-02-05 13:42:43 DEBUG juju.worker.rsyslog worker.go:164 Reloading rsyslog configuration
2015-02-05 13:42:43 INFO config-changed Ign http://security.ubuntu.com trusty-security InRelease
2015-02-05 13:42:43 INFO config-changed Ign http://archive.ubuntu.com trusty InRelease
2015-02-05 13:42:43 INFO config-changed Get:1 http://security.ubuntu.com trusty-security Release.gpg [933 B]
2015-02-05 13:42:43 INFO config-changed Ign http://archive.ubuntu.com trusty-updates InRelease
2015-02-05 13:42:43 INFO config-changed Get:2 http://security.ubuntu.com trusty-security Release [62.0 kB]
2015-02-05 13:42:43 INFO config-changed Hit http://archive.ubuntu.com trusty Release.gpg
2015-02-05 13:42:43 INFO config-changed Get:3 http://archive.ubuntu.com trusty-updates Release.gpg [933 B]
2015-02-05 13:42:43 INFO config-changed Hit http://archive.ubuntu.com trusty Release
2015-02-05 13:42:43 INFO config-changed Get:4 http://archive.ubuntu.com trusty-updates Release [62.0 kB]
2015-02-05 13:42:43 INFO config-changed Get:5 http://security.ubuntu.com trusty-security/main Sources [64.8 kB]
2015-02-05 13:42:44 INFO config-changed Get:6 http://security.ubuntu.com trusty-security/universe Sources [17.5 kB]
2015-02-05 13:42:44 INFO config-changed Hit http://archive.ubuntu.com trusty/main Sources
2015-02-05 13:42:44 INFO config-changed Get:7 http://security.ubuntu.com trusty-security/main amd64 Packages [200 kB]
2015-02-05 13:42:44 INFO config-changed Hit http://archive.ubuntu.com trusty/universe Sources
2015-02-05 13:42:44 INFO config-changed Hit http://archive.ubuntu.com trusty/main amd64 Packages
2015-02-05 13:42:44 INFO config-changed Hit http://archive.ubuntu.com trusty/universe amd64 Packages
2015-02-05 13:42:44 INFO config-changed Get:8 http://security.ubuntu.com trusty-security/universe amd64 Packages [85.3 kB]
2015-02-05 13:42:44 INFO config-changed Hit http://archive.ubuntu.com trusty/main Translation-en
2015-02-05 13:42:44 INFO config-changed Hit http://security.ubuntu.com trusty-security/main Translation-en
2015-02-05 13:42:44 INFO config-changed Hit http://archive.ubuntu.com trusty/universe Translation-en
2015-02-05 13:42:44 INFO config-changed Hit http://security.ubuntu.com trusty-security/universe Translation-en
2015-02-05 13:42:44 INFO config-changed Get:9 http://archive.ubuntu.com trusty-updates/main Sources [161 kB]
2015-02-05 13:42:44 INFO config-changed Get:10 http://archive.ubuntu.com trusty-updates/universe Sources [99.9 kB]
2015-02-05 13:42:44 INFO config-changed Get:11 http://archive.ubuntu.com trusty-updates/main amd64 Packages [411 kB]
2015-02-05 13:42:45 INFO config-changed Get:12 http://archive.ubuntu.com trusty-updates/universe amd64 Packages [244 kB]
2015-02-05 13:42:45 INFO config-changed Hit http://archive.ubuntu.com trusty-updates/main Translation-en
2015-02-05 13:42:45 INFO config-changed Hit http://archive.ubuntu.com trusty-updates/universe Translation-en
2015-02-05 13:42:46 INFO config-changed Fetched 1408 kB in 3s (429 kB/s)
2015-02-05 13:42:48 INFO config-changed Reading package lists...
2015-02-05 13:42:48 INFO worker.uniter.jujuc server.go:102 running hook tool "juju-log" ["Installing ['rabbitmq-server', 'python-amqplib'] with options: ['--option=Dpkg::Options::=--force-confold']"]
2015-02-05 13:42:48 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:48 INFO juju-log Installing ['rabbitmq-server', 'python-amqplib'] with options: ['--option=Dpkg::Options::=--force-confold']
2015-02-05 13:42:48 INFO config-changed Reading package lists...
2015-02-05 13:42:48 INFO config-changed Building dependency tree...
2015-02-05 13:42:48 INFO config-changed Reading state information...
2015-02-05 13:42:48 INFO config-changed python-amqplib is already the newest version.
2015-02-05 13:42:48 INFO config-changed rabbitmq-server is already the newest version.
2015-02-05 13:42:48 INFO config-changed The following packages were automatically installed and are no longer required:
2015-02-05 13:42:48 INFO config-changed   libfreetype6 os-prober
2015-02-05 13:42:48 INFO config-changed Use 'apt-get autoremove' to remove them.
2015-02-05 13:42:48 INFO config-changed 0 upgraded, 0 newly installed, 0 to remove and 3 not upgraded.
2015-02-05 13:42:48 INFO worker.uniter.jujuc server.go:102 running hook tool "open-port" ["5672/TCP"]
2015-02-05 13:42:48 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:48 INFO worker.uniter.jujuc server.go:102 running hook tool "juju-log" ["Changing ownership of path /var/lib/rabbitmq to rabbitmq:rabbitmq"]
2015-02-05 13:42:48 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:48 INFO juju-log Changing ownership of path /var/lib/rabbitmq to rabbitmq:rabbitmq
2015-02-05 13:42:48 INFO worker.uniter.jujuc server.go:102 running hook tool "juju-log" ["Changing perms of path /var/lib/rabbitmq "]
2015-02-05 13:42:48 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:48 INFO juju-log Changing perms of path /var/lib/rabbitmq 
2015-02-05 13:42:48 INFO worker.uniter.jujuc server.go:102 running hook tool "config-get" ["management_plugin" "--format=json"]
2015-02-05 13:42:48 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO config-changed Plugin configuration unchanged.
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "close-port" ["55672/TCP"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "config-get" ["ssl" "--format=json"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "config-get" ["ssl_enabled" "--format=json"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "config-get" ["ssl_key" "--format=json"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "config-get" ["ssl_cert" "--format=json"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "config-get" ["ssl_port" "--format=json"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "close-port" ["5671/TCP"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-ids" ["--format=json" "amqp"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "amqp:32" "-" "rabbitmq-server/1"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "amqp:35" "-" "rabbitmq-server/1"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "amqp:40" "-" "rabbitmq-server/1"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "amqp:44" "-" "rabbitmq-server/1"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "amqp:49" "-" "rabbitmq-server/1"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "amqp:53" "-" "rabbitmq-server/1"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "amqp:60" "-" "rabbitmq-server/1"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "amqp:64" "-" "rabbitmq-server/1"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "amqp:86" "-" "rabbitmq-server/1"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "amqp:90" "-" "rabbitmq-server/1"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-ids" ["--format=json" "ha"]
2015-02-05 13:42:49 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:49 INFO config-changed  * Restarting message broker rabbitmq-server
2015-02-05 13:42:55 INFO config-changed    ...done.
2015-02-05 13:42:55 INFO worker.uniter.jujuc server.go:102 running hook tool "juju-log" ["/usr/bin/rsync -r --delete --executability /var/lib/juju/agents/unit-rabbitmq-server-1/charm/scripts/check_rabbit
mq.py /usr/local/lib/nagios/plugins/check_rabbitmq.py"]
2015-02-05 13:42:55 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:55 INFO juju-log /usr/bin/rsync -r --delete --executability /var/lib/juju/agents/unit-rabbitmq-server-1/charm/scripts/check_rabbitmq.py /usr/local/lib/nagios/plugins/check_rabbitmq.py
2015-02-05 13:42:55 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-ids" ["--format=json" "nrpe-external-master"]
2015-02-05 13:42:55 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:55 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-list" ["--format=json" "-r" "nrpe-external-master:128"]
2015-02-05 13:42:55 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:55 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "nrpe-external-master:128" "-" "nrpe-external-master/46"]
2015-02-05 13:42:55 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:55 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-ids" ["--format=json" "cluster"]
2015-02-05 13:42:55 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:55 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-get" ["--format=json" "-r" "cluster:19" "nagios-rabbitmq-server-1.passwd" "rabbitmq-server/1"]
2015-02-05 13:42:55 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:55 INFO worker.uniter.jujuc server.go:102 running hook tool "juju-log" ["vhost (nagios-rabbitmq-server-1) already exists."]
2015-02-05 13:42:55 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:55 INFO juju-log vhost (nagios-rabbitmq-server-1) already exists.
2015-02-05 13:42:55 INFO config-changed Setting permissions for user "nagios-rabbitmq-server-1" in vhost "nagios-rabbitmq-server-1" ...
2015-02-05 13:42:55 INFO config-changed ...done.
2015-02-05 13:42:55 INFO worker.uniter.jujuc server.go:102 running hook tool "config-get" ["--format=json"]
2015-02-05 13:42:55 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:55 INFO config-changed  * Stopping nagios-nrpe nagios-nrpe
2015-02-05 13:42:56 INFO config-changed    ...done.
2015-02-05 13:42:57 INFO config-changed  * Starting nagios-nrpe nagios-nrpe
2015-02-05 13:42:57 INFO config-changed    ...done.
2015-02-05 13:42:57 INFO worker.uniter.jujuc server.go:102 running hook tool "relation-ids" ["--format=json" "local-monitors"]
2015-02-05 13:42:57 DEBUG worker.uniter.jujuc server.go:103 hook context id "rabbitmq-server/1:config-changed:5433364711736979567"; dir "/var/lib/juju/agents/unit-rabbitmq-server-1/charm"
2015-02-05 13:42:57 INFO juju.worker.uniter uniter.go:494 ran "config-changed" hook
2015-02-05 13:42:57 INFO juju.worker.uniter uniter.go:505 committing "config-changed" hook
2015-02-05 13:42:57 INFO juju.worker.uniter uniter.go:520 committed "config-changed" hook
2015-02-05 13:42:57 DEBUG juju.worker.uniter modes.go:398 ModeConfigChanged exiting
2015-02-05 13:42:57 INFO juju.worker.uniter modes.go:396 ModeContinue starting
2015-02-05 13:42:57 INFO juju.worker.uniter modes.go:48 continuing after "config-changed" hook
2015-02-05 13:42:57 DEBUG juju.worker.uniter modes.go:398 ModeContinue exiting
2015-02-05 13:42:57 INFO juju.worker.uniter modes.go:396 ModeAbide starting
2015-02-05 13:42:57 WARNING juju.worker.uniter.charm git_deployer.go:200 no current staging repo
2015-02-05 13:42:57 DEBUG juju.worker.uniter.filter filter.go:415 want forced upgrade false
2015-02-05 13:42:57 DEBUG juju.worker.uniter.filter filter.go:521 no new charm event
2015-02-05 13:42:57 DEBUG juju.worker.uniter.filter filter.go:371 sent relations event

Revision history for this message

Peter Sabaini (peter-sabaini) wrote on 2015-02-05:

Context: the config-changed hook did indeed fail previously because of another issue which is resolved now

Peter Sabaini (peter-sabaini) on 2015-02-05

tags:

added: canonical-bootstack

Revision history for this message

Junien F (axino) wrote on 2016-01-08:

FWIW I ran into this bug, and got it fixed by removing stale lock files in /var/lib/juju/locks (if there is no juju action running, this directory should be empty) and bouncing machine-0 jujud.

Revision history for this message

Paul Gear (paulgear) wrote on 2016-01-29:

Junien's workaround above worked for me today on a cloud with units stuck in resolved state; it didn't seem necessary to restart jujud-machine-0 (status was clean straight after removing the stale lock files), but I did it anyway.

Paul Gear (paulgear) on 2016-07-27

tags:

added: canonical-is

Revision history for this message

Anastasia (anastasia-macmood) wrote on 2016-10-18:

Lock implementation has been completely re-designed for newer versions of Juju - 1.25.6 and Juju 2.
We believe this has been fixed.

If you are experiencing further failures with Juju 2, please file a bug with newer logs against "juju" launchpad project.

Changed in juju-core:
status:	Triaged → Fix Released

Report a bug

This report contains Public information

Everyone can see this information.

Duplicates of this bug

Bug #1576503

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.