I checked dns reverse lookups and network health, it all looks fine:

http://paste.ubuntu.com/26503247/

On Thu, Feb 1, 2018 at 6:12 PM, David Ames <email address hidden> wrote:
> Analysis
>
> For the current crashdump:
> mysq/0* running db-admin-relation-changed 192.168.33.145
> mysql/1 running leader-settings-changed 192.168.33.151
> mysql/2 running leader-settings-changed 192.168.33.177
>
> The gating from the above change is doing what it says on the tin and
> yet we still see the 'WSREP has not yet prepared node for application
> use' error. Meaning the db-admin-relation-changed is not running until
> the cluster is up.
>
> The error does NOT correlate with a restart of any of the nodes.
>
> The nodes are actively attempting to communicate with each other but
> experiencing a number of timeouts.
>
> The leader node mysq/0 is running db-admin-relation-changed when this
> occurs.
>
> 2018-02-01 22:58:32 DEBUG juju-log db-admin:152: All 3 percona units reporting clustered
> 2018-02-01 22:58:33 DEBUG juju-log db-admin:152: Opening db connection for root@localhost
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed Traceback (most recent call last):
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed   File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/db-admin-relation-changed", line 833, in <module>
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed     main()
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed   File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/db-admin-relation-changed", line 823, in main
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed     hooks.execute(sys.argv)
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed   File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/charmhelpers/core/hookenv.py", line 800, in execute
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed     self._hooks[hook_name]()
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed   File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/db-admin-relation-changed", line 500, in db_changed
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed     password = db_helper.configure_db(addr, db_name, username, admin=admin)
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed   File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/charmhelpers/contrib/database/mysql.py", line 411, in configure_db
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed     self.create_admin_grant(username, remote_ip, password)
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed   File "/var/lib/juju/agents/unit-mysql-0/charm/hooks/charmhelpers/contrib/database/mysql.py", line 145, in create_admin_grant
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed     password))
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed   File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 226, in execute
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed     self.errorhandler(self, exc, value)
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed   File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed     raise errorvalue
> 2018-02-01 22:58:34 DEBUG db-admin-relation-changed _mysql_exceptions.OperationalError: (1047, 'WSREP has not yet prepared node for application use')
>
>
> Timeline from error logs during the 22:58:3x window:
> # Mysql/0
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:30 46217 [Note] WSREP: (e3bdd902, 'tcp://0.0.0.0:4567') connection to peer 99780d27 with addr tcp://192.168.33.177:4567 timed out, no messages seen in PT3S
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:30 46217 [Note] WSREP: (e3bdd902, 'tcp://0.0.0.0:4567') connection to peer c7710d2d with addr tcp://192.168.33.151:4567 timed out, no messages seen in PT3S
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:30 46217 [Note] WSREP: (e3bdd902, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: tcp://192.168.33.151:4567 tcp://192.168.33.177:4567
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:31 46217 [Note] WSREP: (e3bdd902, 'tcp://0.0.0.0:4567') reconnecting to c7710d2d (tcp://192.168.33.151:4567), attempt 0
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:31 46217 [Note] WSREP: (e3bdd902, 'tcp://0.0.0.0:4567') reconnecting to 99780d27 (tcp://192.168.33.177:4567), attempt 0
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:32 46217 [Note] WSREP: evs::proto(e3bdd902, OPERATIONAL, view_id(REG,99780d27,11)) suspecting node: 99780d27
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:32 46217 [Note] WSREP: evs::proto(e3bdd902, OPERATIONAL, view_id(REG,99780d27,11)) suspected node without join message, declaring inactive
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:32 46217 [Note] WSREP: evs::proto(e3bdd902, OPERATIONAL, view_id(REG,99780d27,11)) suspecting node: c7710d2d
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:32 46217 [Note] WSREP: evs::proto(e3bdd902, OPERATIONAL, view_id(REG,99780d27,11)) suspected node without join message, declaring inactive
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: view(view_id(NON_PRIM,99780d27,11) memb {
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: Flow-control interval: [16, 16]
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: Trying to continue unpaused monitor
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: Received NON-PRIMARY.
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: view(view_id(NON_PRIM,e3bdd902,12) memb {
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 2679)
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: Flow-control interval: [16, 16]
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: Trying to continue unpaused monitor
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: Received NON-PRIMARY.
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: New cluster view: global state: 05f68559-079f-11e8-8e3c-ae9f369383fe:2679, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: Setting wsrep_ready to false
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: New cluster view: global state: 05f68559-079f-11e8-8e3c-ae9f369383fe:2679, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: Setting wsrep_ready to false
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:33 46217 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:34 46217 [Note] WSREP: (e3bdd902, 'tcp://0.0.0.0:4567') connection to peer 00000000 with addr tcp://192.168.33.151:4567 timed out, no messages seen in PT3S
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:34 46217 [Note] WSREP: (e3bdd902, 'tcp://0.0.0.0:4567') connection to peer 00000000 with addr tcp://192.168.33.177:4567 timed out, no messages seen in PT3S
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:38 46217 [Note] WSREP: (e3bdd902, 'tcp://0.0.0.0:4567') connection to peer 00000000 with addr tcp://192.168.33.177:4567 timed out, no messages seen in PT3S
> mysql_0/var/log/mysql/error.log:2018-02-01 22:58:38 46217 [Note] WSREP: (e3bdd902, 'tcp://0.0.0.0:4567') connection to peer 00000000 with addr tcp://192.168.33.151:4567 timed out, no messages seen in PT3S
>
> # Mysql/1
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:31 89961 [Note] WSREP: (c7710d2d, 'tcp://0.0.0.0:4567') connection to peer 00000000 with addr tcp://192.168.33.177:4567 timed out, no messages seen in PT3S
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:31 89961 [Note] WSREP: (c7710d2d, 'tcp://0.0.0.0:4567') connection to peer e3bdd902 with addr tcp://192.168.33.145:4567 timed out, no messages seen in PT3S
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:32 89961 [Note] WSREP: evs::proto(c7710d2d, OPERATIONAL, view_id(REG,99780d27,11)) suspecting node: 99780d27
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:32 89961 [Note] WSREP: evs::proto(c7710d2d, OPERATIONAL, view_id(REG,99780d27,11)) suspected node without join message, declaring inactive
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:32 89961 [Note] WSREP: (c7710d2d, 'tcp://0.0.0.0:4567') reconnecting to e3bdd902 (tcp://192.168.33.145:4567), attempt 0
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:33 89961 [Note] WSREP: evs::proto(c7710d2d, GATHER, view_id(REG,99780d27,11)) suspecting node: e3bdd902
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:33 89961 [Note] WSREP: evs::proto(c7710d2d, GATHER, view_id(REG,99780d27,11)) suspected node without join message, declaring inactive
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: view(view_id(NON_PRIM,99780d27,11) memb {
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: Flow-control interval: [16, 16]
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: Trying to continue unpaused monitor
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: Received NON-PRIMARY.
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 2679)
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: view(view_id(NON_PRIM,c7710d2d,12) memb {
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: New cluster view: global state: 05f68559-079f-11e8-8e3c-ae9f369383fe:2679, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: Setting wsrep_ready to false
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: Flow-control interval: [16, 16]
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: Trying to continue unpaused monitor
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: Received NON-PRIMARY.
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: New cluster view: global state: 05f68559-079f-11e8-8e3c-ae9f369383fe:2679, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: Setting wsrep_ready to false
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:34 89961 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:35 89961 [Note] WSREP: (c7710d2d, 'tcp://0.0.0.0:4567') connection to peer 00000000 with addr tcp://192.168.33.177:4567 timed out, no messages seen in PT3S
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:36 89961 [Note] WSREP: (c7710d2d, 'tcp://0.0.0.0:4567') connection to peer 00000000 with addr tcp://192.168.33.145:4567 timed out, no messages seen in PT3S
> mysql_1/var/log/mysql/error.log:2018-02-01 22:58:39 89961 [Note] WSREP: (c7710d2d, 'tcp://0.0.0.0:4567') connection to peer 00000000 with addr tcp://192.168.33.177:4567 timed out, no messages seen in PT3S
>
> # Mysql/2
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:32 40794 [Note] WSREP: evs::proto(99780d27, OPERATIONAL, view_id(REG,99780d27,11)) suspecting node: c7710d2d
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:32 40794 [Note] WSREP: evs::proto(99780d27, OPERATIONAL, view_id(REG,99780d27,11)) suspected node without join message, declaring inactive
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:32 40794 [Note] WSREP: evs::proto(99780d27, OPERATIONAL, view_id(REG,99780d27,11)) suspecting node: e3bdd902
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:32 40794 [Note] WSREP: evs::proto(99780d27, OPERATIONAL, view_id(REG,99780d27,11)) suspected node without join message, declaring inactive
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: view(view_id(NON_PRIM,99780d27,11) memb {
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: view(view_id(NON_PRIM,99780d27,12) memb {
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: Flow-control interval: [16, 16]
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: Trying to continue unpaused monitor
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: Received NON-PRIMARY.
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 2679)
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: New cluster view: global state: 05f68559-079f-11e8-8e3c-ae9f369383fe:2679, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: Setting wsrep_ready to false
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: Flow-control interval: [16, 16]
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: Trying to continue unpaused monitor
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: Received NON-PRIMARY.
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: New cluster view: global state: 05f68559-079f-11e8-8e3c-ae9f369383fe:2679, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: Setting wsrep_ready to false
> mysql_2/var/log/mysql/error.log:2018-02-01 22:58:33 40794 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
>
> Note there are a number of timeouts in various directions between the
> nodes. Note also the error logs have many other timeouts not correlated
> with this error or time period. However, when it does occur it appears
> there is a limit to the number of attempts.
>
> Proximate cause:
>
> Timeouts in communication between the nodes.
>
> Suggestions for next steps:
>
> * Verify that DNS reverse lookups work for the 192.168.33.0/24 address space.
> * Verify network connectivity is robust.
> * Research how to change the PT3S timeout value for resource loaded environments.
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1742683
>
> Title:
>   WSREP has not yet prepared node for application use
>
> Status in OpenStack percona-cluster charm:
>   New
>
> Bug description:
>   A percona cluster unit in my deploy is failing db-admin-relation-
>   changed with this error:
>
>   http://paste.ubuntu.com/26366038/
>
>   Here is the bundle: http://paste.ubuntu.com/26366049/
>
>   I'm seeing this with cs:~openstack-charmers-next/percona-cluster-279
>   and juju 2.3.1.
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/charm-percona-cluster/+bug/1742683/+subscriptions