[MXS-3610] [readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection. Created: 2021-06-10  Updated: 2021-09-13  Resolved: 2021-09-13

Status: Closed
Project: MariaDB MaxScale
Component/s: readwritesplit
Affects Version/s: 2.4.17
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Hartmut Holzgraefe Assignee: markus makela
Resolution: Cannot Reproduce Votes: 1
Labels: None

Sprint: MXS-SPRINT-139

 Description   

On several occasions the message

[readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection.

showed up even though no master failures were seen in the maxscale log.

The connector being used on the client side is MariaDB Connector/J on AIX

The messages seem to be logged at times where we also see

warning: Client requests unknown prepared statement ID '1' that does not map to an internal ID

and

warning: Using unknown prepared statement with ID 0

but there can be a few seconds between these and the TARGET_MASTER messages.

Here's a log snippet starting with maxscale start up to the first occurrence of such messages:

MariaDB MaxScale  /var/log/maxscale/maxscale.log  Thu Jun  3 17:07:07 2021
----------------------------------------------------------------------------
2021-06-03 17:07:07   notice : syslog logging is enabled.
2021-06-03 17:07:07   notice : maxlog logging is enabled.
2021-06-03 17:07:07   warning: Number of threads set to 192, which is greater than the hard maximum of 100. Number of threads adjusted down accordingly.
2021-06-03 17:07:07   notice : Using up to 151.07GiB of memory for query classifier cache
2021-06-03 17:07:07   notice : Working directory: /var/log/maxscale
2021-06-03 17:07:07   notice : The collection of SQLite memory allocation statistics turned off.
2021-06-03 17:07:07   notice : Threading mode of SQLite set to Multi-thread.
2021-06-03 17:07:07   notice : MariaDB MaxScale 2.4.17 started (Commit: a8bfbbe254095d931aed351871fee72ce9ea645c)
2021-06-03 17:07:07   notice : MaxScale is running in process 3882
2021-06-03 17:07:07   notice : Configuration file: /etc/maxscale.cnf
2021-06-03 17:07:07   notice : Log directory: /var/log/maxscale
2021-06-03 17:07:07   notice : Data directory: /var/lib/maxscale
2021-06-03 17:07:07   notice : Module directory: /usr/lib64/maxscale
2021-06-03 17:07:07   notice : Service cache: /var/cache/maxscale
2021-06-03 17:07:07   notice : Worker message queue size: 1.00MiB
2021-06-03 17:07:07   notice : No query classifier specified, using default 'qc_sqlite'.
2021-06-03 17:07:07   notice : Loaded module qc_sqlite: V1.0.0 from /usr/lib64/maxscale/libqc_sqlite.so
2021-06-03 17:07:07   notice : Query classification results are cached and reused. Memory used per thread: 1.51GiB
2021-06-03 17:07:07   notice : The systemd watchdog is Enabled. Internal timeout = 30s
2021-06-03 17:07:07   notice : Loading /etc/maxscale.cnf.
2021-06-03 17:07:07   notice : /etc/maxscale.cnf.d does not exist, not reading.
2021-06-03 17:07:07   notice : Runtime configuration changes have been done to MaxScale. Loading persisted configuration files and applying them on top of the main configuration file. These changes can override the values of the main configuration file: To revert them, remove all the files in '/var/lib/maxscale/maxscale.cnf.d'.
2021-06-03 17:07:07   notice : Loading /var/lib/maxscale/maxscale.cnf.d/core-monitor.cnf.
[...]
2021-06-03 17:07:07   notice : Loading /var/lib/maxscale/maxscale.cnf.d/ibs-coredb-dr2.cnf.
2021-06-03 17:07:07   notice : Loaded module mariadbbackend: V2.0.0 from /usr/lib64/maxscale/libmariadbbackend.so
2021-06-03 17:07:07   notice : Loaded module mariadbclient: V1.1.0 from /usr/lib64/maxscale/libmariadbclient.so
2021-06-03 17:07:07   notice : [readconnroute] Initialise readconnroute router module.
2021-06-03 17:07:07   notice : Loaded module readconnroute: V2.0.0 from /usr/lib64/maxscale/libreadconnroute.so
2021-06-03 17:07:07   notice : Loaded module hintfilter: V1.0.0 from /usr/lib64/maxscale/libhintfilter.so
2021-06-03 17:07:07   notice : Loaded module topfilter: V1.0.1 from /usr/lib64/maxscale/libtopfilter.so
2021-06-03 17:07:07   notice : Loaded module qlafilter: V1.1.1 from /usr/lib64/maxscale/libqlafilter.so
2021-06-03 17:07:07   warning: Missing slashes (/) around a regular expression is deprecated: 'exclude=select|show|set|commit|use|'.
2021-06-03 17:07:07   warning: Missing quotes (") around a quoted string is deprecated: 'separator=,'.
2021-06-03 17:07:07   notice : [readwritesplit] Initializing statement-based read/write split router module.
2021-06-03 17:07:07   notice : Loaded module readwritesplit: V1.1.0 from /usr/lib64/maxscale/libreadwritesplit.so
2021-06-03 17:07:07   notice : [mariadbmon] Initialise the MariaDB Monitor module.
2021-06-03 17:07:07   notice : Loaded module mariadbmon: V1.5.0 from /usr/lib64/maxscale/libmariadbmon.so
2021-06-03 17:07:07   notice : Loaded module mariadbbackendauth: V1.0.0 from /usr/lib64/maxscale/libmariadbbackendauth.so
2021-06-03 17:07:07   notice : Encrypted password file /var/lib/maxscale/.secrets can't be accessed (No such file or directory). Password encryption is not used.
2021-06-03 17:07:07   notice : Loaded module mariadbauth: V1.1.0 from /usr/lib64/maxscale/libmariadbauth.so
2021-06-03 17:07:07   notice : Started REST API on [127.0.0.1]:8989
2021-06-03 17:07:07   notice : MaxScale started with 100 worker threads, each with a stack size of 8388608 bytes.
2021-06-03 17:07:07   notice : Starting a total of 2 services...
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dc1' charset: utf8
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dc1' version: 10.5.9-6-MariaDB-enterprise-log
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dc2' charset: utf8
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dc2' version: 10.5.9-6-MariaDB-enterprise-log
2021-06-03 17:07:07   notice : [MariaDBAuth] [RW-Service-core] Loaded 576 MySQL users for listener 'RW-listener-core' from server 'ibs-coredb-dc1' with checksum 0xa8b8f9ac.
2021-06-03 17:07:07   notice : Listening for connections at [::]:43306
2021-06-03 17:07:07   notice : Service 'RW-Service-core' started (1/2)
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dc4' charset: utf8
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dc4' version: 10.5.9-6-MariaDB-enterprise-log
2021-06-03 17:07:07   notice : [MariaDBAuth] [ROL-Service-bsscore] Loaded 576 MySQL users for listener 'ROL-listener-bsscore' from server 'ibs-coredb-dc4' with checksum 0xa8b8f9ac.
2021-06-03 17:07:07   notice : Listening for connections at [::]:43308
2021-06-03 17:07:07   notice : Service 'ROL-Service-bsscore' started (2/2)
2021-06-03 17:07:07   notice : Loaded server states from journal file: /var/lib/maxscale/core-monitor/monitor.dat
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dc3' charset: utf8
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dc3' version: 10.5.9-6-MariaDB-enterprise-log
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dr1' charset: utf8
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dr1' version: 10.5.9-6-MariaDB-enterprise-log
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dr2' charset: utf8
2021-06-03 17:07:07   notice : Server 'ibs-coredb-dr2' version: 10.5.9-6-MariaDB-enterprise-log
2021-06-03 17:12:35   notice : (1) [MariaDBAuth] [RW-Service-core] Loaded 576 MySQL users for listener 'RW-listener-core' from server 'ibs-coredb-dc2' with checksum 0x1a0e3cc9.
2021-06-03 17:12:35   warning: (1) [MariaDBAuth] RW-Service-core: login attempt for user 'kui'@[::ffff:10.0.10.37]:41670, authentication failed. Wrong password.
2021-06-03 21:13:17   notice : Loaded server states from journal file: /var/lib/maxscale/core-monitor/monitor.dat
2021-06-03 21:13:21   notice : Loaded server states from journal file: /var/lib/maxscale/core-monitor/monitor.dat
2021-06-03 21:13:21   notice : Loaded server states from journal file: /var/lib/maxscale/core-monitor/monitor.dat
2021-06-03 22:20:41   notice : Updated service 'RW-Service-core': transaction_replay=true
2021-06-03 22:21:13   notice : Updated service 'RW-Service-core': transaction_replay_max_size=200Mi
2021-06-03 22:21:42   notice : Updated service 'RW-Service-core': transaction_replay_attempts=10
2021-06-03 22:22:30   notice : Updated service 'RW-Service-core': transaction_replay_retry_on_deadlock=true
2021-06-03 22:24:04   notice : Updated service 'RW-Service-core': transaction_replay_max_size=500Mi
2021-06-03 23:42:55   notice : Updated 'passive' from 'false' to 'true'
2021-06-03 23:43:42   notice : Updated 'passive' from 'true' to 'false'
2021-06-04 07:45:45   warning: Client requests unknown prepared statement ID '1' that does not map to an internal ID
2021-06-04 07:45:45   warning: Client requests unknown prepared statement ID '1' that does not map to an internal ID
2021-06-04 07:45:45   warning: Using unknown prepared statement with ID 0
2021-06-04 07:45:45   warning: Using unknown prepared statement with ID 0
2021-06-04 07:45:45   warning: Client requests unknown prepared statement ID '1' that does not map to an internal ID
2021-06-04 07:45:45   warning: Using unknown prepared statement with ID 0
2021-06-04 07:45:45   warning: Client requests unknown prepared statement ID '1' that does not map to an internal ID
2021-06-04 07:45:45   warning: Client requests unknown prepared statement ID '1' that does not map to an internal ID
2021-06-04 07:45:45   warning: Client requests unknown prepared statement ID '1' that does not map to an internal ID
2021-06-04 07:45:45   warning: Client requests unknown prepared statement ID '1' that does not map to an internal ID
2021-06-04 07:45:45   warning: Client requests unknown prepared statement ID '1' that does not map to an internal ID
2021-06-04 07:45:45   warning: Using unknown prepared statement with ID 0
2021-06-04 07:45:45   warning: Client requests unknown prepared statement ID '1' that does not map to an internal ID
2021-06-04 07:45:45   warning: Using unknown prepared statement with ID 0
2021-06-04 07:45:45   warning: Using unknown prepared statement with ID 0
2021-06-04 07:45:45   warning: Using unknown prepared statement with ID 0
2021-06-04 07:45:45   warning: Using unknown prepared statement with ID 0
2021-06-04 07:45:45   warning: Using unknown prepared statement with ID 0
2021-06-04 07:45:45   warning: Client requests unknown prepared statement ID '1' that does not map to an internal ID (subsequent similar messages suppressed for 10000 milliseconds)
2021-06-04 07:45:45   warning: Using unknown prepared statement with ID 0 (subsequent similar messages suppressed for 10000 milliseconds)
2021-06-04 07:45:54   error  : [readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection.
2021-06-04 07:45:54   error  : [readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection.
2021-06-04 07:45:54   error  : [readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection.
2021-06-04 07:45:54   error  : [readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection.
2021-06-04 07:45:54   error  : [readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection.
2021-06-04 07:45:54   error  : [readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection.
2021-06-04 07:45:54   error  : [readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection.
2021-06-04 07:45:54   error  : [readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection.
2021-06-04 07:45:54   error  : [readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection.
2021-06-04 07:45:54   error  : [readwritesplit] Could not find valid server for target type TARGET_MASTER, closing connection. (subsequent similar messages suppressed for 10000 milliseconds)
[...]

There are two servers known to the readwritesplit routers, neither of their error logs showed anything special at the times these messages were logged on the maxscale side.

We unfortunately also don't have any hint yet towards what queries may have been causing this.



 Comments   
Comment by Wagner Bianchi (Inactive) [ 2021-06-10 ]

Running a sysbench on 2.5.11, I had the below message, which is very similar:

2021-06-09 19:53:39.844   warning: (1947) (rwsplit-service) (ps_id_internal_get): Client requests unknown prepared statement ID '0' that does not map to an internal ID
2021-06-09 19:53:39.844   warning: (1947) (rwsplit-service) (get_type): Using unknown prepared statement with ID 0
2021-06-09 19:53:39.846   warning: (1953) (rwsplit-service) (ps_id_internal_get): Client requests unknown prepared statement ID '0' that does not map to an internal ID
2021-06-09 19:53:39.846   warning: (1953) (rwsplit-service) (get_type): Using unknown prepared statement with ID 0
2021-06-09 19:53:39.852   warning: (1946) (rwsplit-service) (ps_id_internal_get): Client requests unknown prepared statement ID '0' that does not map to an internal ID
2021-06-09 19:53:39.852   warning: (1946) (rwsplit-service) (get_type): Using unknown prepared statement with ID 0

The sysbench command to repeat this:

sysbench --test=/usr/share/sysbench/oltp_read_write.lua --table_size=10000 --mysql-db=db --tables=20 --mysql-user=mdbapp --mysql-password=${pass} --mysql-port=3306 --mysql-host=10.225.16.15 --db-driver=mysql --threads=64 --events=0 --time=60 --rand-type=uniform --report-interval=10 prepare
--
sysbench --test=/usr/share/sysbench/oltp_read_write.lua --table_size=10000 --mysql-db=db --tables=20 --mysql-user=mdbapp --mysql-password=${pass}  --mysql-port=3306 --mysql-host=10.225.16.15 --db-driver=mysql --threads=64 --events=0 --time=360 --rand-type=uniform --report-interval=10 run

For this MaxScale, I have a MariaDB Cluster with three nodes. Though, GaleraMon + ReadWriteSplit Router.

Comment by markus makela [ 2021-07-12 ]

hholzgra can you add the affected version?

Comment by markus makela [ 2021-09-13 ]

I'll close this as Cannot Reproduce since there's no clear indication of anything that would trigger this to happen. There's extra logging added to that part of the code so if it ever happens again, we'll know more.

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