Clients unable to authenticate after pods' initial state transfer

[solsson]

I did a rolling replace of pods now with empty - larger - volumes. After that clients received ER_HOST_NOT_PRIVILEGED and MariaDB logged lines like 2018-07-31 5:18:06 140261701723904 [Warning] IP address '10.0.7.26' could not be resolved: Name or service not known.

The rolling replace of persistent volumes meant all nodes started afresh from state transfer, logged as:

2018-07-31  4:42:43 139965199542016 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 68306)
2018-07-31  4:42:43 139965605660416 [Note] WSREP: State transfer required: 
	Group state: cb1f8096-65a4-11e8-95a2-1a202ed178a3:68306
	Local state: 00000000-0000-0000-0000-000000000000:-1
2018-07-31  4:42:43 139965605660416 [Note] WSREP: New cluster view: global state: cb1f8096-65a4-11e8-95a2-1a202ed178a3:68306, view# 24: Primary, number of nodes: 3, my index: 0, protocol version 3
2018-07-31  4:42:43 139965605660416 [Warning] WSREP: Gap in state sequence. Need state transfer.
2018-07-31  4:42:43 139965191149312 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'joiner' --address '10.0.7.43' --datadir '/data/db/'   --parent '103'  '' '
MySQL init process in progress...
2018-07-31  4:42:43 139965605660416 [Note] WSREP: Prepared SST request: rsync|10.0.7.43:4444/rsync_sst
2018-07-31  4:42:43 139965605660416 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2018-07-31  4:42:43 139965605660416 [Note] WSREP: REPL Protocols: 8 (3, 2)
2018-07-31  4:42:43 139965605660416 [Note] WSREP: Assign initial position for certification: 68306, protocol version: 3
2018-07-31  4:42:43 139965456377600 [Note] WSREP: Service thread queue flushed.
2018-07-31  4:42:43 139965605660416 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (cb1f8096-65a4-11e8-95a2-1a202ed178a3): 1 (Operation not permitted)
	 at galera/src/replicator_str.cpp:prepare_for_IST():482. IST will be unavailable.
2018-07-31  4:42:43 139965199542016 [Note] WSREP: Member 0.0 (mariadb-2) requested state transfer from '*any*'. Selected 1.0 (mariadb-1)(SYNCED) as donor.
2018-07-31  4:42:43 139965199542016 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 68306)
2018-07-31  4:42:43 139965605660416 [Note] WSREP: Requesting state transfer: success, donor: 1
2018-07-31  4:42:43 139965605660416 [Note] WSREP: GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> cb1f8096-65a4-11e8-95a2-1a202ed178a3:68306
MySQL init process in progress...
2018-07-31  4:42:45 139965422806784 [Note] WSREP: (28f31447, 'tcp://0.0.0.0:4567') turning message relay requesting off
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
2018-07-31  4:43:08 139965199542016 [Note] WSREP: 1.0 (mariadb-1): State transfer to 0.0 (mariadb-2) complete.
2018-07-31  4:43:08 139965199542016 [Note] WSREP: Member 1.0 (mariadb-1) synced with group.
WSREP_SST: [INFO] Joiner cleanup. rsync PID: 152 (20180731 04:43:09.247)
MySQL init process in progress...
WSREP_SST: [INFO] Joiner cleanup done. (20180731 04:43:09.755)
2018-07-31  4:43:09 139965607159744 [Note] WSREP: SST complete, seqno: 68306

It turns out that after the state transfer SELECT host, user FROM mysql.user; returns an empty user table.

The solution was to re-create the users, but oddly if I didn't do a DROP first I got ERROR 1396 (HY000): Operation CREATE USER failed for 'myuser'@'%':

MariaDB [(none)]> DROP USER 'myuser';
Query OK, 0 rows affected (0.03 sec)

MariaDB [(none)]> 
MariaDB [(none)]> CREATE USER 'myuser'@'%'  ...
Query OK, 0 rows affected (0.16 sec)

MariaDB [(none)]> 
MariaDB [(none)]> GRANT ALL PRIVILEGES ON mydb.* TO 'myuser'@'%';
Query OK, 0 rows affected (0.01 sec)

All the actual data from other databases appear to be intact.

The state transfer above was from the first rotated pod. Next one logged

2018-07-31  4:57:04 140341984134912 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 68310)
2018-07-31  4:57:04 140342383351552 [Note] WSREP: State transfer required: 
	Group state: cb1f8096-65a4-11e8-95a2-1a202ed178a3:68310
	Local state: 00000000-0000-0000-0000-000000000000:-1
2018-07-31  4:57:04 140342383351552 [Note] WSREP: New cluster view: global state: cb1f8096-65a4-11e8-95a2-1a202ed178a3:68310, view# 30: Primary, number of nodes: 3, my index: 0, protocol version 3
2018-07-31  4:57:04 140342383351552 [Warning] WSREP: Gap in state sequence. Need state transfer.
2018-07-31  4:57:04 140341975742208 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'joiner' --address '10.0.13.44' --datadir '/data/db/'   --parent '98'  '' '
MySQL init process in progress...
MySQL init process in progress...
2018-07-31  4:57:06 140342383351552 [Note] WSREP: Prepared SST request: rsync|10.0.13.44:4444/rsync_sst
2018-07-31  4:57:06 140342383351552 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2018-07-31  4:57:06 140342383351552 [Note] WSREP: REPL Protocols: 8 (3, 2)
2018-07-31  4:57:06 140342383351552 [Note] WSREP: Assign initial position for certification: 68310, protocol version: 3
2018-07-31  4:57:06 140342099846912 [Note] WSREP: Service thread queue flushed.
2018-07-31  4:57:06 140342383351552 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (cb1f8096-65a4-11e8-95a2-1a202ed178a3): 1 (Operation not permitted)
	 at galera/src/replicator_str.cpp:prepare_for_IST():482. IST will be unavailable.
2018-07-31  4:57:06 140341984134912 [Note] WSREP: Member 0.0 (mariadb-1) requested state transfer from '*any*'. Selected 1.0 (mariadb-2)(SYNCED) as donor.
2018-07-31  4:57:06 140341984134912 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 68310)
2018-07-31  4:57:06 140342383351552 [Note] WSREP: Requesting state transfer: success, donor: 1
2018-07-31  4:57:06 140342383351552 [Note] WSREP: GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> cb1f8096-65a4-11e8-95a2-1a202ed178a3:68310
MySQL init process in progress...
2018-07-31  4:57:07 140341999032064 [Note] WSREP: (2ae99905, 'tcp://0.0.0.0:4567') turning message relay requesting off
MySQL init process in progress...
2018-07-31  4:57:08 140341984134912 [Note] WSREP: 1.0 (mariadb-2): State transfer to 0.0 (mariadb-1) complete.
2018-07-31  4:57:08 140341984134912 [Note] WSREP: Member 1.0 (mariadb-2) synced with group.
MySQL init process in progress...
WSREP_SST: [INFO] Joiner cleanup. rsync PID: 147 (20180731 04:57:09.567)
WSREP_SST: [INFO] Joiner cleanup done. (20180731 04:57:10.111)
MySQL init process in progress...
2018-07-31  4:57:10 140342384850880 [Note] WSREP: SST complete, seqno: 68310
2018-07-31  4:57:10 140342384850880 [Note] InnoDB: For Galera, using innodb_lock_schedule_algorithm=fcfs
2018-07-31  4:57:10 140342384850880 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-07-31  4:57:10 140342384850880 [Note] InnoDB: Uses event mutexes
2018-07-31  4:57:10 140342384850880 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-07-31  4:57:10 140342384850880 [Note] InnoDB: Using Linux native AIO
2018-07-31  4:57:10 140342384850880 [Note] InnoDB: Number of pools: 1
2018-07-31  4:57:10 140342384850880 [Note] InnoDB: Using SSE2 crc32 instructions
2018-07-31  4:57:10 140342384850880 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2018-07-31  4:57:10 140342384850880 [Note] InnoDB: Completed initialization of buffer pool
2018-07-31  4:57:10 140341035341568 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-07-31  4:57:10 140342384850880 [Note] InnoDB: Highest supported file format is Barracuda.
2018-07-31  4:57:10 140342384850880 [Note] InnoDB: Starting crash recovery from checkpoint LSN=116143358
MySQL init process in progress...
2018-07-31  4:57:12 140342384850880 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-07-31  4:57:12 140342384850880 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-07-31  4:57:12 140342384850880 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-07-31  4:57:12 140342384850880 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-07-31  4:57:13 140342384850880 [Note] InnoDB: Waiting for purge to start
2018-07-31  4:57:13 140342384850880 [Note] InnoDB: 5.7.22 started; log sequence number 116143367
2018-07-31  4:57:13 140340799465216 [Note] InnoDB: Loading buffer pool(s) from /data/db/ib_buffer_pool
MySQL init process in progress...
2018-07-31  4:57:13 140340799465216 [Note] InnoDB: Buffer pool(s) load completed at 180731  4:57:13
2018-07-31  4:57:14 140342384850880 [Note] Plugin 'FEEDBACK' is disabled.
MySQL init process in progress...
2018-07-31  4:57:14 140342384850880 [Note] WSREP: Signalling provider to continue.
2018-07-31  4:57:14 140342384850880 [Note] WSREP: SST received: cb1f8096-65a4-11e8-95a2-1a202ed178a3:68310
2018-07-31  4:57:14 140341984134912 [Note] WSREP: 0.0 (mariadb-1): State transfer from 1.0 (mariadb-2) complete.
2018-07-31  4:57:14 140341984134912 [Note] WSREP: Shifting JOINER -> JOINED (TO: 68310)
2018-07-31  4:57:14 140342384850880 [Note] Reading of all Master_info entries succeded
2018-07-31  4:57:14 140342384850880 [Note] Added new Master_info '' to hash table
2018-07-31  4:57:14 140342384850880 [Note] mysqld: ready for connections.
Version: '10.2.16-MariaDB-1:10.2.16+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
2018-07-31  4:57:14 140341984134912 [Note] WSREP: Member 0.0 (mariadb-1) synced with group.
2018-07-31  4:57:14 140341984134912 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 68310)
2018-07-31  4:57:14 140342383351552 [Note] WSREP: Synchronized with group, ready for connections
2018-07-31  4:57:14 140342383351552 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

2018-07-31  4:57:15 140341552326400 [Note] mysqld (initiated by: unknown): Normal shutdown
2018-07-31  4:57:15 140341552326400 [Note] WSREP: Stop replication
2018-07-31  4:57:15 140341552326400 [Note] WSREP: Closing send monitor...
2018-07-31  4:57:15 140341552326400 [Note] WSREP: Closed send monitor.
2018-07-31  4:57:15 140341552326400 [Note] WSREP: gcomm: terminating thread
2018-07-31  4:57:15 140341552326400 [Note] WSREP: gcomm: joining thread
2018-07-31  4:57:15 140341552326400 [Note] WSREP: gcomm: closing backend