hook amqp-relation-changed fails but succeeds on retry

[David Coronel]

Installing 3 units of Landscape with landscape-server charm rev 35 and rabbitmq-server charm rev 97 sometimes fails on one unit with the following:

28 Jan 2020 14:15:32Z juju-unit error hook failed: "amqp-relation-changed"

The charm retries a few times and eventually succeeds:

$ juju show-status-log landscape-server/2
Time Type Status Message
28 Jan 2020 14:14:15Z juju-unit executing running db-relation-changed hook
28 Jan 2020 14:14:19Z juju-unit idle
28 Jan 2020 14:15:19Z juju-unit executing running amqp-relation-changed hook
28 Jan 2020 14:15:32Z juju-unit error hook failed: "amqp-relation-changed"
28 Jan 2020 14:15:37Z juju-unit executing running amqp-relation-changed hook
28 Jan 2020 14:15:48Z juju-unit error hook failed: "amqp-relation-changed"
28 Jan 2020 14:15:58Z juju-unit executing running amqp-relation-changed hook
28 Jan 2020 14:16:08Z juju-unit error hook failed: "amqp-relation-changed"
28 Jan 2020 14:16:32Z juju-unit executing running amqp-relation-changed hook
28 Jan 2020 14:16:51Z workload maintenance Starting services.
28 Jan 2020 14:17:12Z workload active
28 Jan 2020 14:17:19Z juju-unit executing running db-relation-changed hook
28 Jan 2020 14:17:29Z workload maintenance Restarting services.
28 Jan 2020 14:17:51Z workload active
28 Jan 2020 14:18:11Z juju-unit executing running amqp-relation-changed hook
28 Jan 2020 14:18:23Z workload maintenance Restarting services.
28 Jan 2020 14:18:45Z workload active
28 Jan 2020 14:19:01Z workload maintenance Restarting services.
28 Jan 2020 14:19:24Z workload active
28 Jan 2020 14:19:25Z juju-unit idle

The /var/log/juju/unit-landscape-server-2.log shows this:

[...]
2020-01-28 14:15:45 DEBUG amqp-relation-changed Hit:9 http://archive.ubuntu.com/ubuntu bionic-backports InRelease
2020-01-28 14:15:46 DEBUG amqp-relation-changed Reading package lists...
2020-01-28 14:15:48 DEBUG amqp-relation-changed Loading site configuration...
2020-01-28 14:15:48 DEBUG amqp-relation-changed Traceback (most recent call last):
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/usr/bin/landscape-schema", line 12, in <module>
2020-01-28 14:15:48 DEBUG amqp-relation-changed canonical.landscape.scripts.schema.run()
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/opt/canonical/landscape/canonical/landscape/scripts/schema.py", line 281, in run
2020-01-28 14:15:48 DEBUG amqp-relation-changed _set_two_phase_commit_if_available(zstorm)
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/opt/canonical/landscape/canonical/landscape/scripts/schema.py", line 532, in _set_two_phase_commit_if_available
2020-01-28 14:15:48 DEBUG amqp-relation-changed store = zstorm.get(name)
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/usr/lib/python2.7/dist-packages/storm/zope/zstorm.py", line 177, in get
2020-01-28 14:15:48 DEBUG amqp-relation-changed return self.create(name, default_uri)
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/usr/lib/python2.7/dist-packages/storm/zope/zstorm.py", line 153, in create
2020-01-28 14:15:48 DEBUG amqp-relation-changed store = Store(database)
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/usr/lib/python2.7/dist-packages/storm/store.py", line 74, in __init__
2020-01-28 14:15:48 DEBUG amqp-relation-changed self._connection = database.connect(self._event)
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/usr/lib/python2.7/dist-packages/storm/database.py", line 500, in connect
2020-01-28 14:15:48 DEBUG amqp-relation-changed return self.connection_factory(self, event)
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/usr/lib/python2.7/dist-packages/storm/database.py", line 188, in __init__
2020-01-28 14:15:48 DEBUG amqp-relation-changed self._raw_connection = self._database.raw_connect()
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/usr/lib/python2.7/dist-packages/storm/databases/postgres.py", line 410, in raw_connect
2020-01-28 14:15:48 DEBUG amqp-relation-changed raw_connection = psycopg2.connect(self._dsn)
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/usr/lib/python2.7/dist-packages/psycopg2/__init__.py", line 130, in connect
2020-01-28 14:15:48 DEBUG amqp-relation-changed conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
2020-01-28 14:15:48 DEBUG amqp-relation-changed psycopg2.OperationalError: FATAL: pg_hba.conf rejects connection for host "10.10.50.216", user "jujuadmin_landscape-server", database "p
ostgres", SSL on
2020-01-28 14:15:48 DEBUG amqp-relation-changed FATAL: pg_hba.conf rejects connection for host "10.10.50.216", user "jujuadmin_landscape-server", database "postgres", SSL off
2020-01-28 14:15:48 DEBUG amqp-relation-changed
2020-01-28 14:15:48 DEBUG amqp-relation-changed Traceback (most recent call last):
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/var/lib/juju/agents/unit-landscape-server-2/charm/hooks/amqp-relation-changed", line 9, in <module>
2020-01-28 14:15:48 DEBUG amqp-relation-changed sys.exit(hook())
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/var/lib/juju/agents/unit-landscape-server-2/charm/hooks/lib/hook.py", line 24, in __call__
2020-01-28 14:15:48 DEBUG amqp-relation-changed self._run()
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/var/lib/juju/agents/unit-landscape-server-2/charm/hooks/lib/services.py", line 92, in _run
2020-01-28 14:15:48 DEBUG amqp-relation-changed manager.manage()
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/var/lib/juju/agents/unit-landscape-server-2/charm/hooks/charmhelpers/core/services/base.py", line 135, in manage
2020-01-28 14:15:48 DEBUG amqp-relation-changed self.reconfigure_services()
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/var/lib/juju/agents/unit-landscape-server-2/charm/hooks/charmhelpers/core/services/base.py", line 189, in reconfigure_services
2020-01-28 14:15:48 DEBUG amqp-relation-changed self.fire_event('data_ready', service_name)
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/var/lib/juju/agents/unit-landscape-server-2/charm/hooks/charmhelpers/core/services/base.py", line 234, in fire_event
2020-01-28 14:15:48 DEBUG amqp-relation-changed callback(self, service_name, event_name)
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/var/lib/juju/agents/unit-landscape-server-2/charm/hooks/lib/callbacks/scripts.py", line 41, in __call__
2020-01-28 14:15:48 DEBUG amqp-relation-changed self._run(SCHEMA_SCRIPT, options)
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/var/lib/juju/agents/unit-landscape-server-2/charm/hooks/lib/callbacks/scripts.py", line 28, in _run
2020-01-28 14:15:48 DEBUG amqp-relation-changed self._subprocess.check_call(command)
2020-01-28 14:15:48 DEBUG amqp-relation-changed File "/usr/lib/python2.7/subprocess.py", line 190, in check_call
2020-01-28 14:15:48 DEBUG amqp-relation-changed raise CalledProcessError(retcode, cmd)
2020-01-28 14:15:48 DEBUG amqp-relation-changed subprocess.CalledProcessError: Command '['/usr/bin/landscape-schema', '--bootstrap']' returned non-zero exit status 1
2020-01-28 14:15:48 ERROR juju.worker.uniter.operation runhook.go:132 hook "amqp-relation-changed" failed: exit status 1
[...]

The rabbitmq-server charm is set to min-cluster-size 3:

  landscape-rabbitmq-server:
    charm: cs:rabbitmq-server
    bindings:
      "": *oam-space
      cluster: *oam-space
      amqp: *oam-space
    options:
      min-cluster-size: 3
    num_units: 3