Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Cannot Reproduce
-
2.4.17
-
None
-
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.