Details
-
Bug
-
Status: Closed (View Workflow)
-
Minor
-
Resolution: Fixed
-
21.06.18, 22.08.15, 23.02.12, 23.08.8, 24.02.4, 25.01.1
-
None
-
RHEL-9
Description
After updating MaxScale from 21.06.17 to 21.06.18 we started seeing the following message in MaxScale's log file for one particular SQL client:
2024-12-22 05:00:03 warning: (2553) MaxScale has encountered an unexpected situation: Unknown prepared statement handler (3) given to MaxScale for COM_STMT_EXECUTE by 'freescout_de'@'172.16.4.41'. Add 'session_trace=200' under the [maxscale] section to enable session level tracing to make the debugging of this problem easier.
The cluster is a master + two slaves and MaxScale uses read-write split for it. The service config is given below. Backends run MariaDB-11.4.
We only see this from one particular web site, which is the only instance of its kind (running a tool named FreeScout, which is PHP using the Symfony framework). We have other web-based tools that use PHP + Symfony, but they do not exhibit such a behaviour.
The client side has not been updated for about 6 months, so the message must be due to the update of MaxScale.
The message corresponds to a run of scheduled tasks via cron; however, not every cron run logs such a message, but about 10-15% of the runs do (the cron runs every minute and we get such a message once every 5-15 min).
The release notes for MaxScale 21.06.18 seem to have only one entry, related to prepared statements, which is MXS-5302. I'm not sure if it is the culprit, though, but I mention it here for the lack of a better candidate.
It may be that the issue is benign, but even if so, it produces quite a lot of noise in the log. We'd love to silence it, if possible.
The platform is RHEL-9. Connector/C is installed from RedHat's packages, version is 3.2.6. PHP is 8.0.30. These are the latest available.
[root@cgdcpwww tmp]# rpm -qa | grep -i mariadb
mariadb-connector-c-config-3.2.6-1.el9_0.noarch
mariadb-connector-c-3.2.6-1.el9_0.x86_64
[root@cgdcpwww tmp]# rpm -qa | grep -i php
php-8.0.30-1.el9_2.x86_64
php-pdo-8.0.30-1.el9_2.x86_64
php-mysqlnd-8.0.30-1.el9_2.x86_64
...
Service config in MaxScale:
[Service-Main]
type=service
router=readwritesplit
servers=cgdcpsql1,cgdcpsql2,cgdcpsql3
enable_root_user=1
user=maxscale
password=filtered
use_sql_variables_in=master
max_slave_connections=1
max_slave_replication_lag=10s
causal_reads=global
connection_timeout=7200s
transaction_replay=1
master_reconnection=1
master_failure_mode=error_on_write
Capture of a session that produces the log message (after setting session_trace=200 in MaxScale's config):
[MariaDBProtocol] Connection attributes: _client_name=mysqlnd _server_host=172.16.70.4
|
Found matching user 'freescout_de'@'%' for client 'freescout_de'@'172.16.4.41' with sufficient privileges.
|
[readwritesplit] (Service-Main); Target connection counts:
|
[readwritesplit] (Service-Main); current operations : 0 in cgdcpsql1 Master, Running
|
[readwritesplit] (Service-Main); current operations : 3 in cgdcpsql2 Slave, Running
|
[readwritesplit] (Service-Main); current operations : 0 in cgdcpsql3 Slave, Running
|
[readwritesplit] (Service-Main); Connected to 'cgdcpsql1'
|
[readwritesplit] (Service-Main); Selected Master: cgdcpsql1
|
[readwritesplit] (Service-Main); Connected to 'cgdcpsql2'
|
[readwritesplit] (Service-Main); Selected Slave: cgdcpsql2
|
Started Service-Main client session [810] for 'freescout_de' from 172.16.4.41 on 'Worker-01'
|
Sending proxy-protocol header 'PROXY TCP4 172.16.4.41 172.16.70.11 43850 3306' to server 'cgdcpsql1'.
|
Connected to 'cgdcpsql1' with thread id 4954813
|
Authentication to 'cgdcpsql1' succeeded.
|
> Autocommit: [enabled], trx is [not open], cmd: (0x03) COM_QUERY, plen: 24, type: QUERY_TYPE_SESSION_WRITE, stmt: use `freescout_de`;
|
(Service-Main); > Autocommit: [enabled], trx is [not open], cmd: (0x03) COM_QUERY, plen: 24, type: QUERY_TYPE_SESSION_WRITE, stmt: use `freescout_de`;
|
[readwritesplit] (Service-Main); Session write, routing to all servers.
|
[readwritesplit] (Service-Main); Route query to master: cgdcpsql1
|
(cgdcpsql2); Storing COM_QUERY while in state 'Handshaking', 1 packet(s) queued: use `freescout_de`;
|
[readwritesplit] (Service-Main); Route query to slave: cgdcpsql2
|
[readwritesplit] (Service-Main); Will return response from 'cgdcpsql1' to the client
|
Sending proxy-protocol header 'PROXY TCP4 172.16.4.41 172.16.70.12 43850 3306' to server 'cgdcpsql2'.
|
[readwritesplit] (Service-Main); Reply complete from 'cgdcpsql1' (OK: 0 warnings)
|
[MariaDBProtocol] (Service-Main); Added COM_QUERY to history with ID 1: use `freescout_de`; (result: OK)
|
> Autocommit: [enabled], trx is [not open], cmd: (0x16) COM_STMT_PREPARE, plen: 53, type: QUERY_TYPE_SESSION_WRITE|QUERY_TYPE_PREPARE_STMT, stmt: set names 'utf8mb4' collate 'utf8mb4_unicode_ci'
|
(Service-Main); > Autocommit: [enabled], trx is [not open], cmd: (0x16) COM_STMT_PREPARE, plen: 53, type: QUERY_TYPE_SESSION_WRITE|QUERY_TYPE_PREPARE_STMT, stmt: set names 'utf8mb4' collate 'utf8mb4_unicode_ci'
|
[readwritesplit] (Service-Main); Session write, routing to all servers.
|
[readwritesplit] (Service-Main); Route query to master: cgdcpsql1
|
(cgdcpsql2); Storing COM_STMT_PREPARE while in state 'Handshaking', 2 packet(s) queued: set names 'utf8mb4' collate 'utf8mb4_unicode_ci'
|
[readwritesplit] (Service-Main); Route query to slave: cgdcpsql2
|
[readwritesplit] (Service-Main); Will return response from 'cgdcpsql1' to the client
|
PS internal ID 2 maps to external ID 105559 on server 'cgdcpsql1'
|
[readwritesplit] (Service-Main); Reply complete from 'cgdcpsql1' (OK: 0 warnings)
|
[MariaDBProtocol] (Service-Main); Added COM_STMT_PREPARE to history with ID 2: set names 'utf8mb4' collate 'utf8mb4_unicode_ci' (result: OK)
|
> Autocommit: [enabled], trx is [not open], cmd: (0x17) COM_STMT_EXECUTE, plen: 14, type: QUERY_TYPE_SESSION_WRITE, stmt: ID: 2
|
(Service-Main); > Autocommit: [enabled], trx is [not open], cmd: (0x17) COM_STMT_EXECUTE, plen: 14, type: QUERY_TYPE_SESSION_WRITE, stmt: ID: 2
|
[readwritesplit] (Service-Main); Session write, routing to all servers.
|
[readwritesplit] (Service-Main); Route query to master: cgdcpsql1
|
(cgdcpsql2); Storing COM_STMT_EXECUTE while in state 'Handshaking', 3 packet(s) queued:
|
[readwritesplit] (Service-Main); Route query to slave: cgdcpsql2
|
[readwritesplit] (Service-Main); Will return response from 'cgdcpsql1' to the client
|
[readwritesplit] (Service-Main); Reply complete from 'cgdcpsql1' (OK: 0 warnings)
|
> Autocommit: [enabled], trx is [not open], cmd: (0x19) COM_STMT_CLOSE, plen: 9, type: QUERY_TYPE_SESSION_WRITE, stmt: ID: 2
|
(Service-Main); > Autocommit: [enabled], trx is [not open], cmd: (0x19) COM_STMT_CLOSE, plen: 9, type: QUERY_TYPE_SESSION_WRITE, stmt: ID: 2
|
[readwritesplit] (Service-Main); Session write, routing to all servers.
|
[readwritesplit] (Service-Main); Route query to master: cgdcpsql1
|
(cgdcpsql2); COM_STMT_CLOSE refers to COM_STMT_PREPARE with ID 2 that is queued for execution, removing both from the queue.
|
[readwritesplit] (Service-Main); Route query to slave: cgdcpsql2
|
> Autocommit: [enabled], trx is [not open], cmd: (0x16) COM_STMT_PREPARE, plen: 50, type: QUERY_TYPE_SESSION_WRITE|QUERY_TYPE_GSYSVAR_WRITE|QUERY_TYPE_PREPARE_STMT, stmt: set session sql_mode='NO_ENGINE_SUBSTITUTION'
|
(Service-Main); > Autocommit: [enabled], trx is [not open], cmd: (0x16) COM_STMT_PREPARE, plen: 50, type: QUERY_TYPE_SESSION_WRITE|QUERY_TYPE_GSYSVAR_WRITE|QUERY_TYPE_PREPARE_STMT, stmt: set session sql_mode='NO_ENGINE_SUBSTITUTION'
|
[readwritesplit] (Service-Main); Session write, routing to all servers.
|
[readwritesplit] (Service-Main); Route query to master: cgdcpsql1
|
(cgdcpsql2); Storing COM_STMT_PREPARE while in state 'Handshaking', 3 packet(s) queued: set session sql_mode='NO_ENGINE_SUBSTITUTION'
|
[readwritesplit] (Service-Main); Route query to slave: cgdcpsql2
|
[readwritesplit] (Service-Main); Will return response from 'cgdcpsql1' to the client
|
Connected to 'cgdcpsql2' with thread id 2715216
|
PS internal ID 3 maps to external ID 105560 on server 'cgdcpsql1'
|
[readwritesplit] (Service-Main); Reply complete from 'cgdcpsql1' (OK: 0 warnings)
|
[MariaDBProtocol] (Service-Main); Added COM_STMT_PREPARE to history with ID 3: set session sql_mode='NO_ENGINE_SUBSTITUTION' (result: OK)
|
Authentication to 'cgdcpsql2' succeeded.
|
Execute COM_QUERY 1 on 'cgdcpsql2': use `freescout_de`;
|
Execute COM_STMT_PREPARE 3 on 'cgdcpsql2': set session sql_mode='NO_ENGINE_SUBSTITUTION'
|
Reply to 1 complete from 'cgdcpsql2'
|
PS internal ID 3 maps to external ID 16816 on server 'cgdcpsql2'
|
Reply to 3 complete from 'cgdcpsql2'
|
2025-01-04 09:29:05 warning: (810) Unknown prepared statement handler (2) given to MaxScale for COM_STMT_EXECUTE by 'freescout_de'@'172.16.4.41'
|
Attachments
Issue Links
- duplicates
-
-
- Closed
-