[MXS-1526] Malformed disk image error Created: 2017-11-16  Updated: 2018-11-27  Resolved: 2018-11-27

Status: Closed
Project: MariaDB MaxScale
Component/s: Authenticator
Affects Version/s: 2.1.10
Fix Version/s: 2.2.2

Type: Bug Priority: Major
Reporter: Wagner Bianchi (Inactive) Assignee: markus makela
Resolution: Fixed Votes: 0
Labels: authentication, mysql
Environment:

CentOS 7.2
[root@maxscale ~]# uname -r
3.10.0-327.4.5.el7.x86_64


Issue Links:
Blocks
is blocked by MXS-1527 SELECT with session var is not supported Closed

 Description   

Folks,

I've been working with the dynamic commands on MariaDB Maxscale 2.1.10 and when loading configurations, I found the below:

2017-11-16 12:48:56   error  : [mysqlmon] No Master can be determined
2017-11-16 12:48:56   error  : (6) [MySQLAuth] Failed to delete old users: database disk image is malformed
2017-11-16 12:48:56   notice : (6) [MySQLAuth] [rwsplit-service] No users were loaded but 'inject_service_user' is enabled. Enabling service credentials for authentication until database users have been successfully loaded.

It's relevant to say that, it's a new Maxscale server but, for existing backends, so, user/password for MySQLAuth does exist.

How to repeat it:

CentOS 7.2 fresh install
Get Maxscale 2.1.10 rpm and setup
Put together a basic config

[root@maxscale ~]# cat ~/maxscale_configs/basic.cnf
[maxscale]
threads=auto
 
[rwsplit-service]
type=service
router=readwritesplit
user=maxuser
passwd=FD08F35D87C442AABA518CFB7471D691
 
[CLI]
type=service
router=cli
 
[CLI Listener]
type=listener
service=CLI
protocol=maxscaled
socket=default

Start maxscale:

[root@maxscale ~]# maxscale -f ~/maxscale_configs/basic.cnf
[root@maxscale ~]#

Execute the below static script:

[root@maxscale ~]# cat maxscale_objects/readwritesplitter.obj
#!/bin/bash
#: the below will create the readwritesplitter for defined replication servers
maxadmin create monitor cluster-monitor mysqlmon
maxadmin alter monitor cluster-monitor user=maxuser password=FD08F35D87C442AABA518CFB7471D691 monitor_interval=10000
maxadmin restart monitor cluster-monitor
maxadmin list monitors
maxadmin create listener rwsplit-service rwsplit-listener 0.0.0.0 4006
maxadmin list listeners
maxadmin list services
maxadmin create server prod_mariadb01 192.168.50.11 3306
maxadmin create server prod_mariadb02 192.168.50.12 3306
maxadmin create server prod_mariadb03 192.168.50.13 3306
maxadmin list servers
maxadmin add server prod_mariadb01 cluster-monitor rwsplit-service
maxadmin add server prod_mariadb02 cluster-monitor rwsplit-service
maxadmin add server prod_mariadb03 cluster-monitor rwsplit-service
maxadmin list servers

Logs will be like below:

MariaDB MaxScale  /var/log/maxscale/maxscale.log  Thu Nov 16 12:05:49 2017
----------------------------------------------------------------------------
2017-11-16 12:05:49   notice : Working directory: /var/log/maxscale
2017-11-16 12:05:49   notice : MariaDB MaxScale 2.1.10 started
2017-11-16 12:05:49   notice : MaxScale is running in process 4269
2017-11-16 12:05:49   notice : Configuration file: /root/maxscale_configs/basic.cnf
2017-11-16 12:05:49   notice : Log directory: /var/log/maxscale
2017-11-16 12:05:49   notice : Data directory: /var/lib/maxscale
2017-11-16 12:05:49   notice : Module directory: /usr/lib64/maxscale
2017-11-16 12:05:49   notice : Service cache: /var/cache/maxscale
2017-11-16 12:05:49   notice : Loading /root/maxscale_configs/basic.cnf.
2017-11-16 12:05:49   notice : /root/maxscale_configs/basic.cnf.d does not exist, not reading.
2017-11-16 12:05:49   notice : [cli] Initialise CLI router module
2017-11-16 12:05:49   notice : Loaded module cli: V1.0.0 from /usr/lib64/maxscale/libcli.so
2017-11-16 12:05:49   notice : [readwritesplit] Initializing statement-based read/write split router module.
2017-11-16 12:05:49   notice : Loaded module readwritesplit: V1.1.0 from /usr/lib64/maxscale/libreadwritesplit.so
2017-11-16 12:05:49   notice : Loaded module maxscaled: V2.0.0 from /usr/lib64/maxscale/libmaxscaled.so
2017-11-16 12:05:49   notice : Loaded module MaxAdminAuth: V2.1.0 from /usr/lib64/maxscale/libMaxAdminAuth.so
2017-11-16 12:05:49   notice : No query classifier specified, using default 'qc_sqlite'.
2017-11-16 12:05:49   notice : Loaded module qc_sqlite: V1.0.0 from /usr/lib64/maxscale/libqc_sqlite.so
2017-11-16 12:05:49   warning: Service 'rwsplit-service' has no listeners defined.
2017-11-16 12:05:49   notice : Listening for connections at [/tmp/maxadmin.sock]:0 with protocol MaxScale Admin
2017-11-16 12:05:49   notice : MaxScale started with 1 server threads.
2017-11-16 12:05:49   notice : Started MaxScale log flusher.
2017-11-16 12:48:56   notice : (2) [mysqlmon] Initialise the MySQL Monitor module.
2017-11-16 12:48:56   notice : (2) Loaded module mysqlmon: V1.5.0 from /usr/lib64/maxscale/libmysqlmon.so
2017-11-16 12:48:56   notice : (2) Created monitor 'cluster-monitor'
2017-11-16 12:48:56   notice : (3) Updated monitor 'cluster-monitor': user=maxuser
2017-11-16 12:48:56   notice : (3) Updated monitor 'cluster-monitor': password=FD08F35D87C442AABA518CFB7471D691
2017-11-16 12:48:56   notice : (3) Updated monitor 'cluster-monitor': monitor_interval=10000
2017-11-16 12:48:56   notice : (6) Loaded module MySQLClient: V1.1.0 from /usr/lib64/maxscale/libMySQLClient.so
2017-11-16 12:48:56   notice : (6) Loaded module MySQLAuth: V1.1.0 from /usr/lib64/maxscale/libMySQLAuth.so
2017-11-16 12:48:56   notice : (6) Using encrypted passwords. Encryption key: '/var/lib/maxscale/.secrets'.
2017-11-16 12:48:56   error  : [mysqlmon] No Master can be determined
2017-11-16 12:48:56   error  : (6) [MySQLAuth] Failed to delete old users: database disk image is malformed
2017-11-16 12:48:56   notice : (6) [MySQLAuth] [rwsplit-service] No users were loaded but 'inject_service_user' is enabled. Enabling service credentials for authentication until database users have been successfully loaded.
2017-11-16 12:48:56   notice : (6) Listening for connections at [0.0.0.0]:4006 with protocol MySQL
2017-11-16 12:48:56   notice : (6) Created listener 'rwsplit-listener' at 0.0.0.0:4006 for service 'rwsplit-service'
2017-11-16 12:48:56   notice : (10) Loaded module MySQLBackend: V2.0.0 from /usr/lib64/maxscale/libMySQLBackend.so
2017-11-16 12:48:56   notice : (10) Loaded module MySQLBackendAuth: V1.0.0 from /usr/lib64/maxscale/libMySQLBackendAuth.so
2017-11-16 12:48:56   notice : (10) Created server 'prod_mariadb01' at 192.168.50.11:3306
2017-11-16 12:48:56   notice : (11) Created server 'prod_mariadb02' at 192.168.50.12:3306
2017-11-16 12:48:56   notice : (12) Created server 'prod_mariadb03' at 192.168.50.13:3306
2017-11-16 12:48:56   notice : (14) Added server 'prod_mariadb01' to monitor 'cluster-monitor'
2017-11-16 12:48:56   notice : (14) Added server 'prod_mariadb01' to service 'rwsplit-service'
^@2017-11-16 12:48:56   notice : Server changed state: prod_mariadb01[192.168.50.11:3306]: new_master. [Running] -> [Master, Running]
2017-11-16 12:48:56   notice : [mysqlmon] A Master Server is now available: 192.168.50.11:3306
2017-11-16 12:48:56   notice : (15) Added server 'prod_mariadb02' to monitor 'cluster-monitor'
2017-11-16 12:48:56   notice : (15) Added server 'prod_mariadb02' to service 'rwsplit-service'
2017-11-16 12:48:56   notice : Server changed state: prod_mariadb02[192.168.50.12:3306]: new_slave. [Running] -> [Slave, Running]
2017-11-16 12:48:56   notice : (16) Added server 'prod_mariadb03' to monitor 'cluster-monitor'
2017-11-16 12:48:56   notice : (16) Added server 'prod_mariadb03' to service 'rwsplit-service'
2017-11-16 12:48:57   notice : Server changed state: prod_mariadb03[192.168.50.13:3306]: new_slave. [Running] -> [Slave, Running]

Thanks folks.



 Comments   
Comment by Wagner Bianchi (Inactive) [ 2017-11-16 ]

Folks,

Another issue I found is that, if I disable the inject_server_user in an attempt to disable that option and don't have that feature on my Maxscale instance, as stated at https://mariadb.com/kb/en/mariadb-enterprise/mariadb-maxscale-21-mysql-authenticator/, I got this below:

2017-11-16 13:52:18   error  : [MySQLAuth] Failed to delete old users: database disk image is malformed
2017-11-16 13:52:18   notice : Server changed state: prod_mariadb01[192.168.50.11:3306]: new_master. [Running] -> [Master, Running]
2017-11-16 13:52:18   notice : Server changed state: prod_mariadb02[192.168.50.12:3306]: new_slave. [Running] -> [Slave, Running]
2017-11-16 13:52:18   notice : Server changed state: prod_mariadb03[192.168.50.13:3306]: new_slave. [Running] -> [Slave, Running]
2017-11-16 13:52:18   notice : [mysqlmon] A Master Server is now available: 192.168.50.11:3306
2017-11-16 13:52:18   error  : [MySQLAuth] Failed to insert database: database disk image is malformed
2017-11-16 13:52:18   error  : [MySQLAuth] Failed to insert database: database disk image is malformed
2017-11-16 13:52:18   error  : [MySQLAuth] Failed to insert database: database disk image is malformed
2017-11-16 13:52:18   error  : [MySQLAuth] Failed to insert database: database disk image is malformed
2017-11-16 13:52:18   error  : [MySQLAuth] Failed to insert database: database disk image is malformed
2017-11-16 13:52:18   error  : [MySQLAuth] Failed to insert database: database disk image is malformed
2017-11-16 13:52:18   error  : [MySQLAuth] Failed to insert database: database disk image is malformed
2017-11-16 13:52:18   error  : [MySQLAuth] Failed to insert database: database disk image is malformed
2017-11-16 13:52:18   error  : [MySQLAuth] Failed to insert database: database disk image is malformed
2017-11-16 13:52:18   error  : [MySQLAuth] Failed to insert database: database disk image is malformed (subsequent similar messages suppressed for 10000 milliseconds)

Another issue is that, as I'm using dynamic configurations, I need to edit the service listener file created at /var/lib/maxscale/maxscale.cnf.d which in this case is rwsplit-listener.cnf and add the authenticator_options=inject_service_user=false.

[root@maxscale maxscale.cnf.d]# cat rwsplit-listener.cnf
[rwsplit-listener]
type=listener
protocol=MySQLClient
service=rwsplit-service
address=0.0.0.0
port=4006
authenticator=MySQLAuth
authenticator_options=inject_service_user=false

But why I think this is a problem, maybe we need a way to pass this as a parameter when creating the listener?

Thanks again, cheers.

Comment by Wagner Bianchi (Inactive) [ 2017-11-16 ]

Folks,

What I did, I removed the underlying sqllite databases used for cache users:

/var/cache/maxscale/router_readwritesplit/listener_readwritesplit/cache/dbusers.db
/var/cache/maxscale/readwritesplit_router/readwritesplit_listener/cache/dbusers.db

And then tested two different situations, one with authenticator_options=inject_service_user=false and the other one removing that variable/configuration for the listener, as the default value will be true, enabled by default. Below the log output:

#: authenticator_options=inject_service_user=false
MariaDB MaxScale  /var/log/maxscale/maxscale.log  Thu Nov 16 14:17:43 2017
----------------------------------------------------------------------------
^@2017-11-16 14:17:43   notice : Working directory: /var/log/maxscale
2017-11-16 14:17:43   notice : MariaDB MaxScale 2.1.10 started
2017-11-16 14:17:43   notice : MaxScale is running in process 4429
2017-11-16 14:17:43   notice : Configuration file: /root/maxscale_configs/basic.cnf
2017-11-16 14:17:43   notice : Log directory: /var/log/maxscale
2017-11-16 14:17:43   notice : Data directory: /var/lib/maxscale
2017-11-16 14:17:43   notice : Module directory: /usr/lib64/maxscale
2017-11-16 14:17:43   notice : Service cache: /var/cache/maxscale
2017-11-16 14:17:43   notice : Loading /root/maxscale_configs/basic.cnf.
2017-11-16 14:17:43   notice : /root/maxscale_configs/basic.cnf.d does not exist, not reading.
2017-11-16 14:17:43   notice : Loading generated configuration files from '/var/lib/maxscale/maxscale.cnf.d'
2017-11-16 14:17:43   notice : Loading /var/lib/maxscale/maxscale.cnf.d/cluster-monitor.cnf.
2017-11-16 14:17:43   notice : Loading /var/lib/maxscale/maxscale.cnf.d/prod_mariadb01.cnf.
2017-11-16 14:17:43   notice : Loading /var/lib/maxscale/maxscale.cnf.d/prod_mariadb02.cnf.
2017-11-16 14:17:43   notice : Loading /var/lib/maxscale/maxscale.cnf.d/prod_mariadb03.cnf.
2017-11-16 14:17:43   notice : Loading /var/lib/maxscale/maxscale.cnf.d/rwsplit-service.cnf.
2017-11-16 14:17:43   notice : Loading /var/lib/maxscale/maxscale.cnf.d/rwsplit-listener.cnf.
2017-11-16 14:17:43   notice : [mysqlmon] Initialise the MySQL Monitor module.
2017-11-16 14:17:43   notice : Loaded module mysqlmon: V1.5.0 from /usr/lib64/maxscale/libmysqlmon.so
2017-11-16 14:17:43   notice : [cli] Initialise CLI router module
2017-11-16 14:17:43   notice : Loaded module cli: V1.0.0 from /usr/lib64/maxscale/libcli.so
2017-11-16 14:17:43   notice : [readwritesplit] Initializing statement-based read/write split router module.
2017-11-16 14:17:43   notice : Loaded module readwritesplit: V1.1.0 from /usr/lib64/maxscale/libreadwritesplit.so
2017-11-16 14:17:43   notice : Loaded module MySQLBackendAuth: V1.0.0 from /usr/lib64/maxscale/libMySQLBackendAuth.so
2017-11-16 14:17:43   notice : Loaded module MySQLAuth: V1.1.0 from /usr/lib64/maxscale/libMySQLAuth.so
2017-11-16 14:17:43   notice : Loaded module maxscaled: V2.0.0 from /usr/lib64/maxscale/libmaxscaled.so
2017-11-16 14:17:43   notice : Loaded module MaxAdminAuth: V2.1.0 from /usr/lib64/maxscale/libMaxAdminAuth.so
2017-11-16 14:17:43   notice : No query classifier specified, using default 'qc_sqlite'.
2017-11-16 14:17:43   notice : Loaded module qc_sqlite: V1.0.0 from /usr/lib64/maxscale/libqc_sqlite.so
2017-11-16 14:17:43   notice : Using encrypted passwords. Encryption key: '/var/lib/maxscale/.secrets'.
2017-11-16 14:17:43   notice : Loaded module MySQLClient: V1.1.0 from /usr/lib64/maxscale/libMySQLClient.so
2017-11-16 14:17:43   notice : Server changed state: prod_mariadb01[192.168.50.11:3306]: new_master. [Running] -> [Master, Running]
2017-11-16 14:17:43   notice : Server changed state: prod_mariadb02[192.168.50.12:3306]: new_slave. [Running] -> [Slave, Running]
2017-11-16 14:17:43   notice : Server changed state: prod_mariadb03[192.168.50.13:3306]: new_slave. [Running] -> [Slave, Running]
2017-11-16 14:17:43   notice : [mysqlmon] A Master Server is now available: 192.168.50.11:3306
2017-11-16 14:18:45   notice : [MySQLAuth] [rwsplit-service] Loaded 11 MySQL users for listener rwsplit-listener.
2017-11-16 14:18:45   notice : Listening for connections at [0.0.0.0]:4006 with protocol MySQL
2017-11-16 14:18:45   notice : Listening for connections at [/tmp/maxadmin.sock]:0 with protocol MaxScale Admin
2017-11-16 14:18:45   notice : MaxScale started with 1 server threads.
2017-11-16 14:18:45   notice : Started MaxScale log flusher.
^@2017-11-16 14:19:11   notice : Waiting for housekeeper to shut down.
2017-11-16 14:19:12   notice : Finished MaxScale log flusher.
2017-11-16 14:19:12   notice : Housekeeper shutting down.
2017-11-16 14:19:12   notice : Housekeeper has shut down.
2017-11-16 14:19:12   notice : MaxScale received signal SIGTERM. Exiting.
2017-11-16 14:19:12   notice : MaxScale is shutting down.
2017-11-16 14:19:12   notice : MaxScale shutdown completed.
2017-11-16 14:19:12   MariaDB MaxScale is shut down.
----------------------------------------------------

and then,

#: without inject_service_user
MariaDB MaxScale  /var/log/maxscale/maxscale.log  Thu Nov 16 14:20:48 2017
----------------------------------------------------------------------------
^@^@2017-11-16 14:20:48   notice : Working directory: /var/log/maxscale
2017-11-16 14:20:48   notice : MariaDB MaxScale 2.1.10 started
2017-11-16 14:20:48   notice : MaxScale is running in process 4438
2017-11-16 14:20:48   notice : Configuration file: /root/maxscale_configs/basic.cnf
2017-11-16 14:20:48   notice : Log directory: /var/log/maxscale
2017-11-16 14:20:48   notice : Data directory: /var/lib/maxscale
2017-11-16 14:20:48   notice : Module directory: /usr/lib64/maxscale
2017-11-16 14:20:48   notice : Service cache: /var/cache/maxscale
2017-11-16 14:20:48   notice : Loading /root/maxscale_configs/basic.cnf.
2017-11-16 14:20:48   notice : /root/maxscale_configs/basic.cnf.d does not exist, not reading.
2017-11-16 14:20:48   notice : Loading generated configuration files from '/var/lib/maxscale/maxscale.cnf.d'
2017-11-16 14:20:48   notice : Loading /var/lib/maxscale/maxscale.cnf.d/cluster-monitor.cnf.
2017-11-16 14:20:48   notice : Loading /var/lib/maxscale/maxscale.cnf.d/prod_mariadb01.cnf.
2017-11-16 14:20:48   notice : Loading /var/lib/maxscale/maxscale.cnf.d/prod_mariadb02.cnf.
2017-11-16 14:20:48   notice : Loading /var/lib/maxscale/maxscale.cnf.d/prod_mariadb03.cnf.
2017-11-16 14:20:48   notice : Loading /var/lib/maxscale/maxscale.cnf.d/rwsplit-service.cnf.
2017-11-16 14:20:48   notice : Loading /var/lib/maxscale/maxscale.cnf.d/rwsplit-listener.cnf.
2017-11-16 14:20:48   notice : [mysqlmon] Initialise the MySQL Monitor module.
2017-11-16 14:20:48   notice : Loaded module mysqlmon: V1.5.0 from /usr/lib64/maxscale/libmysqlmon.so
2017-11-16 14:20:48   notice : [cli] Initialise CLI router module
2017-11-16 14:20:48   notice : Loaded module cli: V1.0.0 from /usr/lib64/maxscale/libcli.so
2017-11-16 14:20:48   notice : [readwritesplit] Initializing statement-based read/write split router module.
2017-11-16 14:20:48   notice : Loaded module readwritesplit: V1.1.0 from /usr/lib64/maxscale/libreadwritesplit.so
2017-11-16 14:20:48   notice : Loaded module MySQLBackendAuth: V1.0.0 from /usr/lib64/maxscale/libMySQLBackendAuth.so
2017-11-16 14:20:48   notice : Loaded module MySQLAuth: V1.1.0 from /usr/lib64/maxscale/libMySQLAuth.so
2017-11-16 14:20:48   notice : Loaded module maxscaled: V2.0.0 from /usr/lib64/maxscale/libmaxscaled.so
2017-11-16 14:20:48   notice : Loaded module MaxAdminAuth: V2.1.0 from /usr/lib64/maxscale/libMaxAdminAuth.so
2017-11-16 14:20:48   notice : No query classifier specified, using default 'qc_sqlite'.
2017-11-16 14:20:48   notice : Loaded module qc_sqlite: V1.0.0 from /usr/lib64/maxscale/libqc_sqlite.so
2017-11-16 14:20:48   notice : Using encrypted passwords. Encryption key: '/var/lib/maxscale/.secrets'.
2017-11-16 14:20:48   notice : Loaded module MySQLClient: V1.1.0 from /usr/lib64/maxscale/libMySQLClient.so
2017-11-16 14:20:49   notice : Server changed state: prod_mariadb01[192.168.50.11:3306]: new_master. [Running] -> [Master, Running]
2017-11-16 14:20:49   notice : Server changed state: prod_mariadb02[192.168.50.12:3306]: new_slave. [Running] -> [Slave, Running]
2017-11-16 14:20:49   notice : Server changed state: prod_mariadb03[192.168.50.13:3306]: new_slave. [Running] -> [Slave, Running]
2017-11-16 14:20:49   notice : [mysqlmon] A Master Server is now available: 192.168.50.11:3306
2017-11-16 14:22:04   notice : [MySQLAuth] [rwsplit-service] Loaded 11 MySQL users for listener rwsplit-listener.
2017-11-16 14:22:04   notice : Listening for connections at [0.0.0.0]:4006 with protocol MySQL
2017-11-16 14:22:04   notice : Listening for connections at [/tmp/maxadmin.sock]:0 with protocol MaxScale Admin
2017-11-16 14:22:04   notice : MaxScale started with 1 server threads.
2017-11-16 14:22:04   notice : Started MaxScale log flusher.

So, let's connect the app:

[root@maxscale maxscale.cnf.d]# ifconfig
enp0s8: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet 192.168.50.100  netmask 255.255.255.0  broadcast 192.168.50.255
        inet6 fe80::a00:27ff:fe84:e9bd  prefixlen 64  scopeid 0x20<link>
        ether 08:00:27:84:e9:bd  txqueuelen 1000  (Ethernet)
        RX packets 206354  bytes 120898385 (115.2 MiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 264015  bytes 27325211 (26.0 MiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
 
[root@maxscale maxscale.cnf.d]# mysql -u wb -p123 -h 192.168.50.100 -P 4006 -e "select @@hostname"
+------------+
| @@hostname |
+------------+
| box02      |
+------------+
 
[root@maxscale maxscale.cnf.d]# maxadmin list servers
Servers.
-------------------+-----------------+-------+-------------+--------------------
Server             | Address         | Port  | Connections | Status
-------------------+-----------------+-------+-------------+--------------------
prod_mariadb01     | 192.168.50.11   |  3306 |           0 | Master, Running
prod_mariadb02     | 192.168.50.12   |  3306 |           0 | Slave, Running <<< box02
prod_mariadb03     | 192.168.50.13   |  3306 |           0 | Slave, Running
-------------------+-----------------+-------+-------------+--------------------

All seems to be good and logs cleaned, but, why did the db got corrupted? Is this something we can do internally the Maxscale to make sure db used for cache can be recycled in case it's presenting malformed problems?

Comment by markus makela [ 2018-11-27 ]

This was fixed in 2.2.

Generated at Thu Feb 08 04:07:25 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.