Unable to upgrade charm, ERROR state changing too quickly; try again soon (excessive contention)

[Frode Nordahl]

I can consistently reproduce this on OpenStack provider with test bundle at https://review.openstack.org/#/c/614050/

Environment:
$ juju version
2.5-beta2-bionic-amd64

$ snap info juju|grep installed:
installed: 2.5-beta2+develop-294ca9f (5992) 70MB classic

Steps to reproduce:
$ git review -d 614050
$ tox -e build
$ tox -c build/builds/octavia/tox.ini -e func-smoke --workdir /tmp/tox
$ juju upgrade-charm octavia --path ./build/builds/octavia

Output:
$ juju --debug upgrade-charm octavia --path ./build/builds/octavia
06:33:29 INFO juju.cmd supercommand.go:56 running juju [2.5-beta2 gc go1.10.4]
06:33:29 DEBUG juju.cmd supercommand.go:57 args: []string{"/snap/juju/5992/bin/juju", "--debug", "upgrade-charm", "octavia", "--path", "./build/builds/octavia"}
06:33:29 INFO juju.juju api.go:67 connecting to API addresses: [10.5.0.11:17070 252.0.11.1:17070]
06:33:29 DEBUG juju.api apiclient.go:883 successfully dialed "wss://252.0.11.1:17070/model/44959819-66f2-49e0-8e62-c3ca6eac8e18/api"
06:33:29 INFO juju.api apiclient.go:603 connection established to "wss://252.0.11.1:17070/model/44959819-66f2-49e0-8e62-c3ca6eac8e18/api"
06:33:29 INFO juju.juju api.go:67 connecting to API addresses: [252.0.11.1:17070 10.5.0.11:17070]
06:33:29 DEBUG juju.api apiclient.go:883 successfully dialed "wss://252.0.11.1:17070/api"
06:33:29 INFO juju.api apiclient.go:603 connection established to "wss://252.0.11.1:17070/api"
06:33:29 DEBUG juju.charm charmdir.go:389 charm is not in revision control directory
06:33:30 DEBUG httpbakery client.go:243 client do POST https://252.0.11.1:17070/model/44959819-66f2-49e0-8e62-c3ca6eac8e18/charms?revision=0&schema=local&series=bionic {
06:33:32 DEBUG httpbakery client.go:245 } -> error <nil>
06:33:32 INFO cmd upgradecharm.go:356 Added charm "local:bionic/octavia-4" to the model.
06:33:33 DEBUG juju.api monitor.go:35 RPC connection died
ERROR state changing too quickly; try again soon (excessive contention)
06:33:33 DEBUG cmd supercommand.go:459 error stack:
state changing too quickly; try again soon (excessive contention)
/build/juju/parts/juju/go/src/github.com/juju/juju/rpc/client.go:149:
/build/juju/parts/juju/go/src/github.com/juju/juju/api/apiclient.go:978:
/build/juju/parts/juju/go/src/github.com/juju/juju/cmd/juju/application/upgradecharm.go:372:

Nothing related seem to appear in the controller logs:
$ juju ssh -m controller 0
# tail /var/log/juju/*.log
==> /var/log/juju/audit.log <==
{"errors":{"conversation-id":"95c8ef34135ff5ea","connection-id":"3B6E","request-id":6,"when":"2018-11-28T06:33:33Z","errors":[{"message":"state changing too quickly; try again soon","code":"excessive contention"}]}}
{"conversation":{"who":"admin","what":"/snap/juju/5992/bin/juju ssh -m controller 0","when":"2018-11-28T06:33:48Z","model-name":"controller","model-uuid":"0e163e6f-a806-40ce-80ae-1ff9f9bc42d4","conversation-id":"786bbae5b4b48d39","connection-id":"3B78"}}
{"request":{"conversation-id":"786bbae5b4b48d39","connection-id":"3B78","request-id":2,"when":"2018-11-28T06:33:48Z","facade":"SSHClient","method":"Proxy","version":2}}
{"errors":{"conversation-id":"786bbae5b4b48d39","connection-id":"3B78","request-id":2,"when":"2018-11-28T06:33:48Z","errors":null}}
{"request":{"conversation-id":"786bbae5b4b48d39","connection-id":"3B78","request-id":3,"when":"2018-11-28T06:33:48Z","facade":"SSHClient","method":"AllAddresses","version":2}}
{"errors":{"conversation-id":"786bbae5b4b48d39","connection-id":"3B78","request-id":3,"when":"2018-11-28T06:33:48Z","errors":[null]}}
{"request":{"conversation-id":"786bbae5b4b48d39","connection-id":"3B78","request-id":4,"when":"2018-11-28T06:33:48Z","facade":"SSHClient","method":"PublicKeys","version":2}}
{"errors":{"conversation-id":"786bbae5b4b48d39","connection-id":"3B78","request-id":4,"when":"2018-11-28T06:33:48Z","errors":[null]}}
{"request":{"conversation-id":"786bbae5b4b48d39","connection-id":"3B78","request-id":5,"when":"2018-11-28T06:33:48Z","facade":"SSHClient","method":"PublicKeys","version":2}}
{"errors":{"conversation-id":"786bbae5b4b48d39","connection-id":"3B78","request-id":5,"when":"2018-11-28T06:33:48Z","errors":[null]}}

==> /var/log/juju/lease.log <==
2018/11/28 05:55:35.715788 claimed "27492a51-4422-46e2-8705-e1fa1cb20a9a:application-leadership#ubuntu#" for "ubuntu/0"
2018/11/28 05:56:30.364442 claimed "44959819-66f2-49e0-8e62-c3ca6eac8e18:application-leadership#nova-compute#" for "nova-compute/0"
2018/11/28 05:57:37.756319 claimed "27492a51-4422-46e2-8705-e1fa1cb20a9a:application-leadership#neutron-openvswitch#" for "neutron-openvswitch/0"
2018/11/28 05:58:12.432183 claimed "44959819-66f2-49e0-8e62-c3ca6eac8e18:application-leadership#neutron-openvswitch#" for "neutron-openvswitch/0"
2018/11/28 05:58:23.021055 claimed "44959819-66f2-49e0-8e62-c3ca6eac8e18:application-leadership#mysql#" for "mysql/0"
2018/11/28 06:01:45.254228 claimed "44959819-66f2-49e0-8e62-c3ca6eac8e18:application-leadership#keystone#" for "keystone/0"
2018/11/28 06:04:29.709140 claimed "328675b3-4a4c-427c-8342-f5b99c9168c0:singular-controller#328675b3-4a4c-427c-8342-f5b99c9168c0#" for "machine-0"
2018/11/28 06:05:00.313128 expired "27492a51-4422-46e2-8705-e1fa1cb20a9a:singular-controller#27492a51-4422-46e2-8705-e1fa1cb20a9a#"
2018/11/28 06:05:05.340528 expired "27492a51-4422-46e2-8705-e1fa1cb20a9a:application-leadership#ubuntu#"
2018/11/28 06:05:07.358030 expired "27492a51-4422-46e2-8705-e1fa1cb20a9a:application-leadership#neutron-openvswitch#"

==> /var/log/juju/logsink.log <==
44959819-66f2-49e0-8e62-c3ca6eac8e18: unit-octavia-1 2018-11-28 06:33:54 WARNING unit.octavia/1.juju-log server.go:284 Not adding haproxy listen stanza for octavia-api_public port is already in use
44959819-66f2-49e0-8e62-c3ca6eac8e18: unit-octavia-1 2018-11-28 06:33:54 DEBUG unit.octavia/1.juju-log server.go:284 Changing permissions on existing content: 33184 -> 416
44959819-66f2-49e0-8e62-c3ca6eac8e18: unit-octavia-1 2018-11-28 06:33:54 DEBUG unit.octavia/1.update-status logger.go:53 octavia-api (enabled by site administrator)
44959819-66f2-49e0-8e62-c3ca6eac8e18: unit-octavia-1 2018-11-28 06:33:54 INFO unit.octavia/1.juju-log server.go:284 Invoking reactive handler: reactive/layer_openstack.py:61:run_default_update_status
44959819-66f2-49e0-8e62-c3ca6eac8e18: unit-octavia-1 2018-11-28 06:33:54 INFO unit.octavia/1.juju-log server.go:284 Invoking reactive handler: hooks/relations/tls-certificates/requires.py:101:broken:certificates
44959819-66f2-49e0-8e62-c3ca6eac8e18: unit-octavia-1 2018-11-28 06:33:54 DEBUG unit.octavia/1.juju-log server.go:284 Running _assess_status()
44959819-66f2-49e0-8e62-c3ca6eac8e18: unit-octavia-1 2018-11-28 06:33:57 DEBUG unit.octavia/1.update-status logger.go:53 active
44959819-66f2-49e0-8e62-c3ca6eac8e18: unit-octavia-1 2018-11-28 06:33:57 DEBUG unit.octavia/1.update-status logger.go:53 active
44959819-66f2-49e0-8e62-c3ca6eac8e18: unit-octavia-1 2018-11-28 06:33:57 DEBUG unit.octavia/1.update-status logger.go:53 active
44959819-66f2-49e0-8e62-c3ca6eac8e18: unit-octavia-1 2018-11-28 06:33:57 DEBUG unit.octavia/1.update-status logger.go:53 active

==> /var/log/juju/machine-0.log <==
2018-11-28 05:49:42 ERROR juju.state allwatcher.go:438 getting a public address for unit "octavia/2" failed:
2018-11-28 05:49:42 ERROR juju.state allwatcher.go:442 getting a private address for unit "octavia/2" failed:
2018-11-28 05:49:43 ERROR juju.state allwatcher.go:438 getting a public address for unit "octavia/2" failed:
2018-11-28 05:49:43 ERROR juju.state allwatcher.go:442 getting a private address for unit "octavia/2" failed:
2018-11-28 05:49:44 ERROR juju.state allwatcher.go:438 getting a public address for unit "rabbitmq-server/0" failed:
2018-11-28 05:49:44 ERROR juju.state allwatcher.go:442 getting a private address for unit "rabbitmq-server/0" failed:
2018-11-28 05:49:44 ERROR juju.state allwatcher.go:438 getting a public address for unit "rabbitmq-server/0" failed:
2018-11-28 05:49:44 ERROR juju.state allwatcher.go:442 getting a private address for unit "rabbitmq-server/0" failed:
2018-11-28 06:04:27 ERROR juju.worker.dependency engine.go:632 "environ-tracker" manifold worker returned unexpected error: cannot read environ config: model "27492a51-4422-46e2-8705-e1fa1cb20a9a": settings not found (not found)
2018-11-28 06:04:27 ERROR juju.worker.dependency engine.go:632 "model-upgrader" manifold worker returned unexpected error: model 27492a51-4422-46e2-8705-e1fa1cb20a9a has been removed

# exit
$ date
Wed Nov 28 06:35:33 UTC 2018

[Richard Harding (rharding)]

Thanks for the bug report Frode. We're aware of this issue when transactions fail to apply. There's some WIP from stickupkid we believe will address this. Once that lands we'll ask if you can help test it out and see if it's corrected.

[Linda Guo (lihuiguo)]

saw the same issue in a customer environment

$ juju upgrade-charm graylog
Added charm-store charm "graylog", revision 50 in channel stable, to the model
ERROR cannot upgrade application "graylog" to charm "cs:graylog-50": state changing too quickly; try again soon (excessive contention)

Juju version 2.9.12