Comment 1 for bug 1947669

Revision history for this message
Xav Paice (xavpaice) wrote :

Reproduced on Bionic. Xenial works fine.

Appears to be an issue starting Grafana:
2021-10-19 21:23:54 INFO unit.grafana-b/0.juju-log server.go:327 Reactive main running for hook upgrade-charm
2021-10-19 21:23:55 ERROR unit.grafana-b/0.juju-log server.go:327 Unable to find implementation for relation: requires of register-application
2021-10-19 21:23:56 INFO unit.grafana-b/0.juju-log server.go:327 Initializing Snap Layer
2021-10-19 21:23:56 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: reactive/snap.py:117:upgrade_charm
2021-10-19 21:23:56 WARNING unit.grafana-b/0.upgrade-charm logger.go:60 All snaps up to date.
2021-10-19 21:23:56 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: reactive/tls_client.py:186:remove_states
2021-10-19 21:23:56 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: reactive/grafana.py:652:wipe_nrpe_checks
2021-10-19 21:23:56 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: reactive/grafana.py:1186:check_adminuser
2021-10-19 21:23:56 INFO unit.grafana-b/0.juju-log server.go:327 Checking for existing users, loop 1 of 6
2021-10-19 21:24:01 INFO unit.grafana-b/0.juju-log server.go:327 check_adminuser::sqlite3.OperationError: no such table: user
2021-10-19 21:24:01 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: hooks/relations/tls-certificates/requires.py:109:broken:certificates
2021-10-19 21:24:01 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: hooks/relations/http/provides.py:15:broken:website
2021-10-19 21:24:02 INFO juju.worker.uniter.operation runhook.go:152 ran "upgrade-charm" hook (via explicit, bespoke hook script)
2021-10-19 21:24:02 INFO juju.worker.uniter resolver.go:154 found queued "config-changed" hook
2021-10-19 21:24:03 INFO unit.grafana-b/0.juju-log server.go:327 Reactive main running for hook config-changed
2021-10-19 21:24:03 ERROR unit.grafana-b/0.juju-log server.go:327 Unable to find implementation for relation: requires of register-application
2021-10-19 21:24:04 INFO unit.grafana-b/0.juju-log server.go:327 Initializing Snap Layer
2021-10-19 21:24:04 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: reactive/grafana.py:323:config_changed
2021-10-19 21:24:04 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: reactive/grafana.py:483:setup_grafana
2021-10-19 21:24:04 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: reactive/grafana.py:652:wipe_nrpe_checks
2021-10-19 21:24:04 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: hooks/relations/tls-certificates/requires.py:109:broken:certificates
2021-10-19 21:24:04 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: hooks/relations/http/provides.py:15:broken:website
2021-10-19 21:24:04 INFO unit.grafana-b/0.juju-log server.go:327 Invoking reactive handler: reactive/grafana.py:585:restart_grafana
2021-10-19 21:24:04 INFO unit.grafana-b/0.juju-log server.go:327 Starting grafana-server
2021-10-19 21:24:04 INFO unit.grafana-b/0.juju-log server.go:327 Retrying '_block_until_port_open' 10 more times (delay=2)
2021-10-19 21:24:06 INFO unit.grafana-b/0.juju-log server.go:327 Retrying '_block_until_port_open' 9 more times (delay=4)
2021-10-19 21:24:10 INFO unit.grafana-b/0.juju-log server.go:327 Retrying '_block_until_port_open' 8 more times (delay=6)
2021-10-19 21:24:17 INFO unit.grafana-b/0.juju-log server.go:327 Retrying '_block_until_port_open' 7 more times (delay=8)
2021-10-19 21:24:25 INFO unit.grafana-b/0.juju-log server.go:327 Retrying '_block_until_port_open' 6 more times (delay=10)
2021-10-19 21:24:35 INFO unit.grafana-b/0.juju-log server.go:327 Retrying '_block_until_port_open' 5 more times (delay=12)
2021-10-19 21:24:47 INFO unit.grafana-b/0.juju-log server.go:327 Retrying '_block_until_port_open' 4 more times (delay=14)
2021-10-19 21:25:01 INFO unit.grafana-b/0.juju-log server.go:327 Retrying '_block_until_port_open' 3 more times (delay=16)
2021-10-19 21:25:17 INFO unit.grafana-b/0.juju-log server.go:327 Retrying '_block_until_port_open' 2 more times (delay=18)
2021-10-19 21:25:35 INFO unit.grafana-b/0.juju-log server.go:327 Retrying '_block_until_port_open' 1 more times (delay=20)
2021-10-19 21:25:55 ERROR unit.grafana-b/0.juju-log server.go:327 Hook error:
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-grafana-b-0/.venv/lib/python3.6/site-packages/charms/reactive/__init__.py", line 74, in main
    bus.dispatch(restricted=restricted_mode)
  File "/var/lib/juju/agents/unit-grafana-b-0/.venv/lib/python3.6/site-packages/charms/reactive/bus.py", line 390, in dispatch
    _invoke(other_handlers)
  File "/var/lib/juju/agents/unit-grafana-b-0/.venv/lib/python3.6/site-packages/charms/reactive/bus.py", line 359, in _invoke
    handler.invoke()
  File "/var/lib/juju/agents/unit-grafana-b-0/.venv/lib/python3.6/site-packages/charms/reactive/bus.py", line 181, in invoke
    self._action(*args)
  File "/var/lib/juju/agents/unit-grafana-b-0/charm/reactive/grafana.py", line 608, in restart_grafana
    _block_until_port_open()
  File "/var/lib/juju/agents/unit-grafana-b-0/.venv/lib/python3.6/site-packages/charmhelpers/core/decorators.py", line 40, in _retry_on_exception_inner_2
    return f(*args, **kwargs)
  File "/var/lib/juju/agents/unit-grafana-b-0/charm/reactive/grafana.py", line 1488, in _block_until_port_open
    raise Exception("port %s is closed" % port)
Exception: port 3000 is closed

grafana.log:

t=2021-10-19T21:24:07+0000 lvl=info msg="Config loaded from" logger=settings file=/usr/share/grafana/conf/defaults.ini
t=2021-10-19T21:24:07+0000 lvl=info msg="Config loaded from" logger=settings file=/etc/grafana/grafana.ini
t=2021-10-19T21:24:07+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.data=/var/lib/grafana"
t=2021-10-19T21:24:07+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.logs=/var/log/grafana"
t=2021-10-19T21:24:07+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.plugins=/var/lib/grafana/plugins"
t=2021-10-19T21:24:07+0000 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.provisioning=/etc/grafana/provisioning"
t=2021-10-19T21:24:07+0000 lvl=info msg="Path Home" logger=settings path=/usr/share/grafana
t=2021-10-19T21:24:07+0000 lvl=info msg="Path Data" logger=settings path=/var/lib/grafana
t=2021-10-19T21:24:07+0000 lvl=info msg="Path Logs" logger=settings path=/var/log/grafana
t=2021-10-19T21:24:07+0000 lvl=info msg="Path Plugins" logger=settings path=/var/lib/grafana/plugins
t=2021-10-19T21:24:07+0000 lvl=info msg="Path Provisioning" logger=settings path=/etc/grafana/provisioning
t=2021-10-19T21:24:07+0000 lvl=info msg="App mode production" logger=settings
t=2021-10-19T21:24:07+0000 lvl=info msg="Connecting to DB" logger=sqlstore dbtype=sqlite3
t=2021-10-19T21:24:07+0000 lvl=warn msg="SQLite database file has broader permissions than it should" logger=sqlstore path=/var/lib/grafana/grafana.db mode=-rw-r--r-- expected=-rw-r-----
t=2021-10-19T21:24:07+0000 lvl=info msg="Starting DB migrations" logger=migrator
t=2021-10-19T21:24:07+0000 lvl=info msg="Executing migration" logger=migrator id="create migration_log table"
t=2021-10-19T21:24:07+0000 lvl=eror msg="Executing migration failed" logger=migrator id="create migration_log table" error="attempt to write a readonly database"
t=2021-10-19T21:24:07+0000 lvl=eror msg="Exec failed" logger=migrator error="attempt to write a readonly database" sql="CREATE TABLE IF NOT EXISTS `migration_log` (\n`id` INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL\n, `migration_id` TEXT NOT NULL\n, `sql` TEXT NOT NULL\n, `success` INTEGER NOT NULL\n, `error` TEXT NOT NULL\n, `timestamp` DATETIME NOT NULL\n);"