[MXS-2490] Unknown prepared statement handler (0) given to mysqld_stmt_execute Created: 2019-05-15  Updated: 2021-01-25  Resolved: 2019-06-24

Status: Closed
Project: MariaDB MaxScale
Component/s: readwritesplit
Affects Version/s: 2.3.6
Fix Version/s: 2.3.9, 2.3.10

Type: Bug Priority: Major
Reporter: balyn Assignee: markus makela
Resolution: Fixed Votes: 0
Labels: asterisk, mariadb, maxscale, odbc, unixODBC
Environment:

Scheme:
App <odbc> MaxScale <readwritesplit> M-S Cluster

App:
CentOS Linux release 7.6.1810 (Core)
Kernel 5.0.7-1.el7.elrepo.x86_64
Asterisk 16.3.0 with ODBC driver
unixODBC-2.3.1-11
MariaDB Connector/ODBC 3.1

MaxScale:
CentOS Linux release 7.6.1810 (Core)
Kernel 5.0.10-1.el7.elrepo.x86_64
MariaDB MaxScale 2.3.6 (Commit: 03dc969cf203decb4d0bc65280fe4f901da87830)

Master:
CentOS Linux release 7.6.1810 (Core)
Kernel 5.0.7-1.el7.elrepo.x86_64
Ver 15.1 Distrib 10.3.14-MariaDB

Slave:
CentOS Linux release 7.6.1810 (Core)
Kernel 5.0.10-1.el7.elrepo.x86_64
Ver 15.1 Distrib 10.3.14-MariaDB

Attachments: PNG File image-2019-05-15-09-49-45-652.png     Text File maxscale.txt     File maxscale_log_info_version_string.log    
Issue Links:
Relates
relates to ODBC-261 Connector deploys direct execution, e... Closed

 Description   

I made MariaDB Master-Slave cluster for Asterisk VoIP server. For balancing I use MaxScale with RWsplit strategy.

Fragment of maxscale.cnf with splitter section:

[splitter]
 
type=service
 
router=readwritesplit
 
servers=dbmaster,dbslave
 
user=maxscale
 
password=
 
connection_keepalive=120
 
master_accept_reads=true

Full maxscale.cnf attached.

Got this error (maxscale.log) after connecting my Asterisk server to MaxScale:

2019-05-14 13:33:25   warning: (9) Client requests unknown prepared statement ID '4294967295' that does not map to an internal ID
 
2019-05-14 13:33:25   warning: (9) Using unknown prepared statement with ID 0

I try to connect Astrerisk directly to Master and this works well - it can write and read, without any errors. What's why I think this is MaxScale issue.

I get a traffic dump from my Asterisk server:

After connecting, Asterisk send this SQL query:

SELECT TABLE_SCHEMA AS TABLE_CAT, NULL AS TABLE_SCHEM, TABLE_NAME, COLUMN_NAME, CASE DATA_TYPE WHEN 'bit' THEN @dt:= IF(NUMERIC_PRECISION=1,(-7), (-2)) WHEN 'tinyint' THEN @dt:=(-6) WHEN 'smallint' THEN @dt:=5 WHEN 'year' THEN @dt:= 5 WHEN 'mediumint' THEN @dt:=4 WHEN 'int' THEN @dt:=4 WHEN 'bigint' THEN @dt:=(-5) WHEN 'blob' THEN @dt:=(-4) WHEN 'tinyblob' THEN @dt:=(-4) WHEN 'mediumblob' THEN @dt:=(-4) WHEN 'longblob' THEN @dt:=(-4) WHEN 'decimal' THEN @dt:=3 WHEN 'float' THEN @dt:=IF(NUMERIC_SCALE IS NULL,7, 3) WHEN 'double' THEN @dt:=IF(NUMERIC_SCALE IS NULL,8, 3) WHEN 'binary' THEN @dt:=(-2) WHEN 'varbinary' THEN @dt:=(-3) WHEN 'text' THEN @dt:=(-1) WHEN 'tinytext' THEN @dt:=(-1) WHEN 'mediumtext' THEN @dt:=(-1) WHEN 'longtext' THEN @dt:=(-1) WHEN 'char' THEN @dt:=1 WHEN 'enum' THEN @dt:=1 WHEN 'set' THEN @dt:=1 WHEN 'varchar' THEN @dt:=12 WHEN 'date' THEN @dt:=91 WHEN 'time' THEN @dt:=92 WHEN 'datetime' THEN @dt:=93 WHEN 'timestamp' THEN @dt:=93 ELSE @dt:=(-4)END AS DATA_TYPE, UCASE(IF(COLUMN_TYPE LIKE '%(%)%', CONCAT(SUBSTRING(COLUMN_TYPE,1, LOCATE('(',COLUMN_TYPE) - 1 ), SUBSTRING(COLUMN_TYPE,1+locate(')',COLUMN_TYPE))), COLUMN_TYPE )) AS TYPE_NAME, CAST(CASE WHEN DATA_TYPE = 'bit' THEN @ColSize:=((NUMERIC_PRECISION + 7) / 8) WHEN DATA_TYPE in ('tinyint', 'smallint', 'mediumint', 'int','bigint', 'decimal') THEN @ColSize:=NUMERIC_PRECISION WHEN DATA_TYPE = 'float' THEN if(NUMERIC_SCALE IS NULL, @ColSize:=7, @ColSize:=NUMERIC_PRECISION) WHEN DATA_TYPE = 'double' THEN if(NUMERIC_SCALE IS NULL, @ColSize:=15, @ColSize:=NUMERIC_PRECISION) WHEN DATA_TYPE = 'date' THEN @ColSize:=10 WHEN DATA_TYPE = 'time' THEN @ColSize:=8 WHEN DATA_TYPE = 'year' THEN @ColSize:=4 WHEN DATA_TYPE in ('timestamp', 'datetime') THEN @ColSize:=19 ELSE @ColSize:=CHARACTER_MAXIMUM_LENGTH END AS UNSIGNED) AS COLUMN_SIZE,@tol:=CAST(CASE @dt WHEN (-7) THEN 1 WHEN (-6) THEN 1 WHEN 5 THEN 2 WHEN 4 THEN IF(DATA_TYPE='mediumint',3,4) WHEN (-5) THEN 20 WHEN 7 THEN 4 WHEN 6 THEN 8 WHEN 8 THEN 8 WHEN 9 THEN 6 WHEN 91 THEN 6 WHEN 10 THEN 6 WHEN 92 THEN 6 WHEN 11 THEN 16 WHEN 93 THEN 16 WHEN (-11) THEN 16 WHEN 3 THEN @ColSize + IF(COLUMN_TYPE LIKE '%unsigned',1,2) WHEN (-2) THEN IF(DATA_TYPE='bit', CAST(((NUMERIC_PRECISION + 7) / 8) AS SIGNED), CHARACTER_OCTET_LENGTH) WHEN (-3) THEN CHARACTER_OCTET_LENGTH WHEN (-4) THEN CHARACTER_OCTET_LENGTH ELSE CHARACTER_MAXIMUM_LENGTH*3 END AS SIGNED) AS BUFFER_LENGTH, NUMERIC_SCALE DECIMAL_DIGITS, IF(CHARACTER_OCTET_LENGTH IS NOT NULL, NULL, 10) AS NUM_PREC_RADIX,IF(DATA_TYPE='timestamp', 1, IF(IS_NULLABLE='YES',1,IF(EXTRA='auto_increment', 1, 0))) AS NULLABLE, COLUMN_COMMENT AS REMARKS,COLUMN_DEFAULT AS COLUMN_DEF,CAST(CASE WHEN DATA_TYPE = 'date' THEN 9 WHEN DATA_TYPE = 'time' THEN 9 WHEN DATA_TYPE = 'datetime' THEN 9 WHEN DATA_TYPE = 'timestamp' THEN 9 ELSE @dt END AS SIGNED) SQL_DATA_TYPE,CAST(CASE WHEN DATA_TYPE = 'date' THEN 1 WHEN DATA_TYPE = 'time' THEN 2 WHEN DATA_TYPE = 'datetime' THEN 3 WHEN DATA_TYPE = 'timestamp' THEN 3 ELSE NULL END AS SIGNED) SQL_DATETIME_SUB,IF(CHARACTER_OCTET_LENGTH IS NOT NULL, @tol, IF(DATA_TYPE='bit' AND NUMERIC_PRECISION =1, NULL, CAST((NUMERIC_PRECISION + 7)/8 AS SIGNED))) AS CHAR_OCTET_LENGTH, ORDINAL_POSITION,IF(DATA_TYPE='timestamp', 'YES', IF(IS_NULLABLE='YES','YES',IF(EXTRA='auto_increment', 'YES', 'NO'))) AS IS_NULLABLE FROM INFORMATION_SCHEMA.COLUMNS WHERE TABLE_SCHEMA = DATABASE()AND TABLE_NAME LIKE 'cdr' AND COLUMN_NAME LIKE '%' ORDER BY TABLE_SCHEMA, TABLE_NAME, ORDINAL_POSITION

And MaxScale answer with error 1243:

Unknown prepared statement handler (0) given to mysqld_stmt_execute

Found nothing relevant here, so will be glad if you can help to solve the issue. Once more, It works great with direct Astersik<odbc>Master connection, so issue is related to MaxScale.
Ready to provide any additional info for diagnose and solve it.

 Comments   
Comment by markus makela [ 2019-06-10 ]

An improved error message will be logged in 2.3.8.

Comment by markus makela [ 2019-06-20 ]

Managed to reproduce this and it seems this can happen when a statement is retried when it fails. If this is the same problem, it'll be fixed in 2.3.9.

Comment by markus makela [ 2019-06-24 ]

Tentatively closing this as fixed.

Comment by George Diamantopoulos [ 2019-07-05 ]

Unfortunately I'm having the exact same issue balyn reported with version 2.3.9 as well.

If it helps, this seems to happen when asterisk is configured with ODBC and the driver used is mariadb-connector-odbc 3.1.1 but not (or at least not right away after starting asterisk) when the driver used is libmyodbc 5.1.10-3.

Comment by George Diamantopoulos [ 2019-07-05 ]

I've just tried with latest Oracle libmyodbc binary available for jessie (5.3.13) and was UNable to reproduce the issue.

Could this be a problem with mariadb's libmaodbc instead, I wonder?

Comment by balyn [ 2019-07-06 ]

I would appreciate if Assignee try to reproduce it.
Because it is real problem, I can't use MaxScale for Asterisk Service with maria odbc driver now.

Comment by markus makela [ 2019-07-07 ]

Did the MaxScale log have any errors or warnings? MaxScale 2.3.9 should reply with a different error if the client sent an unknown prepared statement handle.

Comment by George Diamantopoulos [ 2019-07-09 ]

Here's the output from 2.3.9 (some lines skipped, indicated by ellipsis):

2019-07-05 16:30:22   notice : MariaDB MaxScale 2.3.9 started (Commit: 66d6ce6fa598a43b20af052ef6c9f637a3279fa1)
 
...
 
2019-07-05 16:30:22   notice : Initializing statement-based read/write split router module.
 
2019-07-05 16:30:22   notice : Loaded module readwritesplit: V1.1.0 from /usr/lib/x86_64-linux-gnu/maxscale/libreadwritesplit.so
 
2019-07-05 16:30:22   notice : Initialise the MySQL Galera Monitor module.
 
2019-07-05 16:30:22   notice : Loaded module galeramon: V2.0.0 from /usr/lib/x86_64-linux-gnu/maxscale/libgaleramon.so
 
2019-07-05 16:30:22   notice : Loaded module MariaDBBackend: V2.0.0 from /usr/lib/x86_64-linux-gnu/maxscale/libmariadbbackend.so
 
2019-07-05 16:30:22   notice : Loaded module MySQLBackendAuth: V1.0.0 from /usr/lib/x86_64-linux-gnu/maxscale/libmysqlbackendauth.so
 
2019-07-05 16:30:22   notice : Loaded module MaxAdminAuth: V2.1.0 from /usr/lib/x86_64-linux-gnu/maxscale/libmaxadminauth.so
 
2019-07-05 16:30:22   notice : Loaded module MySQLAuth: V1.1.0 from /usr/lib/x86_64-linux-gnu/maxscale/libmysqlauth.so
 
2019-07-05 16:30:22   notice : Housekeeper thread started.
 
2019-07-05 16:30:22   notice : Encrypted password file /var/lib/maxscale/.secrets can't be accessed (No such file or directory). Password encryption is not used.
 
2019-07-05 16:30:22   notice : Loaded server states from journal file: /var/lib/maxscale/Galera-Monitor/monitor.dat
 
2019-07-05 16:30:22   notice : Starting a total of 2 services...
 
2019-07-05 16:30:22   notice : Listening for connections at [/var/run/maxscale/maxadmin.sock]:0 with protocol MaxScale Admin
 
2019-07-05 16:30:22   notice : Service 'MaxAdmin-Service' started (1/2)
 
2019-07-05 16:30:22   notice : [Read-Write-Service] Loaded 310 MySQL users for listener Read-Write-Listener.
 
2019-07-05 16:30:22   notice : Listening for connections at [::]:3306 with protocol MySQL
 
2019-07-05 16:30:22   notice : Service 'Read-Write-Service' started (2/2)
 
2019-07-05 16:30:23   notice : Started REST API on [127.0.0.1]:8989
 
2019-07-05 16:30:23   notice : MaxScale started with 8 worker threads, each with a stack size of 8388608 bytes.
 
2019-07-05 16:30:52   warning: (3) Client requests unknown prepared statement ID '4294967295' that does not map to an internal ID
 
2019-07-05 16:30:52   warning: (3) Using unknown prepared statement with ID 0
 
2019-07-05 16:30:52   error  : (3) Could not find valid server for target type TARGET_MASTER, closing connection.
 
2019-07-05 16:30:52   warning: (3) Client requests unknown prepared statement ID '4294967295' that does not map to an internal ID
 
...
 
2019-07-05 16:30:52   warning: (3) Client requests unknown prepared statement ID '131072' that does not map to an internal ID
 
2019-07-05 16:30:52   warning: (3) Using unknown prepared statement with ID 0
 
2019-07-05 16:30:52   warning: (3) Client requests unknown prepared statement ID '131072' that does not map to an internal ID
 
2019-07-05 16:30:52   warning: (3) Closing unknown prepared statement with ID 0
 
2019-07-05 16:30:52   warning: (3) Client requests unknown prepared statement ID '0' that does not map to an internal ID
 
2019-07-05 16:30:52   warning: (3) Using unknown prepared statement with ID 0
 
2019-07-05 16:30:52   warning: (3) Client requests unknown prepared statement ID '0' that does not map to an internal ID
 
2019-07-05 16:30:52   warning: (3) Closing unknown prepared statement with ID 0
 
2019-07-05 16:30:52   warning: (3) Client requests unknown prepared statement ID '0' that does not map to an internal ID (subsequent similar messages suppressed for 10000 milliseconds)
 
2019-07-05 16:30:52   warning: (3) Using unknown prepared statement with ID 0
 
2019-07-05 16:30:52   warning: (3) Closing unknown prepared statement with ID 0
 
2019-07-05 16:30:52   warning: (3) Using unknown prepared statement with ID 0
 
2019-07-05 16:30:52   warning: (3) Closing unknown prepared statement with ID 0

And here's the same event as logged by 2.3.8:

2019-06-18 10:45:58   notice : MariaDB MaxScale 2.3.8 started (Commit: 814ae196e9e6b2823e5e3ffac174ff5270e7d9d5)
 
...
 
2019-06-24 03:59:40   warning: (7169964) Client requests unknown prepared statement ID '4294967295' that does not map to an internal ID
 
2019-06-24 03:59:40   warning: (7169964) Using unknown prepared statement with ID 0
 
2019-06-24 03:59:40   warning: (7169964) Client requests unknown prepared statement ID '4294967295' that does not map to an internal ID
 
2019-06-24 03:59:40   warning: (7169964) Using unknown prepared statement with ID 0
 
2019-06-24 03:59:40   warning: (7169964) Client requests unknown prepared statement ID '131072' that does not map to an internal ID
 
2019-06-24 03:59:40   warning: (7169964) Using unknown prepared statement with ID 0
 
2019-06-24 03:59:40   warning: (7169964) Client requests unknown prepared statement ID '131072' that does not map to an internal ID
 
2019-06-24 03:59:40   warning: (7169964) Closing unknown prepared statement with ID 0
 
2019-06-24 03:59:40   warning: (7169964) Client requests unknown prepared statement ID '0' that does not map to an internal ID
 
2019-06-24 03:59:40   warning: (7169964) Using unknown prepared statement with ID 0
 
2019-06-24 03:59:40   warning: (7169964) Client requests unknown prepared statement ID '0' that does not map to an internal ID
 
2019-06-24 03:59:40   warning: (7169964) Closing unknown prepared statement with ID 0
 
2019-06-24 03:59:40   warning: (7169964) Client requests unknown prepared statement ID '6710628' that does not map to an internal ID
 
2019-06-24 03:59:40   warning: (7169964) Using unknown prepared statement with ID 0
 
2019-06-24 03:59:40   warning: (7169964) Client requests unknown prepared statement ID '6710628' that does not map to an internal ID
 
2019-06-24 03:59:40   warning: (7169964) Closing unknown prepared statement with ID 0
 
2019-06-24 03:59:40   warning: (7169965) Client requests unknown prepared statement ID '4294967295' that does not map to an internal ID
 
2019-06-24 03:59:40   warning: (7169965) Using unknown prepared statement with ID 0
 
2019-06-24 03:59:40   warning: (7169965) Client requests unknown prepared statement ID '4294967295' that does not map to an internal ID (subsequent similar messages suppressed for 10000 milliseconds)

Comment by markus makela [ 2019-07-09 ]

Thanks for the logs, this clarifies the situation. It looks like the client is using a statement ID that is either not in use or was not returned from the same MaxScale session. gedia if you could confirm that this does not happen with the Oracle ODBC connector, then we know that there's something odd going on with the MariaDB ODBC connector and MaxScale.

Comment by markus makela [ 2019-07-09 ]

Can you try if adding version_string=10.1.14-MariaDB to all the services helps? We suspect that some of the problems might be due to direct execution of prepared statements.

Comment by George Diamantopoulos [ 2019-07-09 ]

I've just performed a test with version_string=10.1.14-MariaDB set for the readwritesplit service and it doesn't seem to make a difference. Out of curiosity, how does the version string affect direct execution?

And yes, I can confirm that this issue does not manifest when using Oracle's ODBC connector for mysql, at least with the versions mentioned in my previous posts.

Comment by markus makela [ 2019-07-09 ]

The MariaDB ODBC connector uses a special command to speed up prepared statement execution by using what is referred to as direct execution. As support for it was added in MariaDB 10.2.2, using a version string lower than this should prevent it from being used but it appears at least some of the errors are not caused by this.

Comment by markus makela [ 2019-07-09 ]

The fix to this will prevent the error with the exact ID of 4294967295. The other errors are still not resolved which means more investigation is needed. Just to be sure, could you check whether this particular error disappeared from the log after adding the version_string?

Client requests unknown prepared statement ID '4294967295' that does not map to an internal ID

If it's possible, can you also add log_info=1 under the maxscale section to enable verbose logging? This would be very helpful in figuring out what is happening in the code.

Comment by George Diamantopoulos [ 2019-07-09 ]

Unfortunately the ID you mentioned still produces errors with custom version_string:

2019-07-09 16:19:21   warning: (3) Client requests unknown prepared statement ID '4294967295' that does not map to an internal ID
 
2019-07-09 16:19:21   warning: (3) Using unknown prepared statement with ID 0
 
2019-07-09 16:19:21   error  : (3) Could not find valid server for target type TARGET_MASTER, closing connection.

I'm attaching logs produced with log_info and version_string. Some irrelevant output has been trimmed, hostnames, IPs and usernames have been masked.

Let me know if I can be of any further assistance. Thanks!

Comment by markus makela [ 2019-07-09 ]

Looks like there's some invalid SQL that is assumed to work:

2019-07-09 16:20:54   info   : (5) > Autocommit: [enabled], trx is [not open], cmd: (0x16) COM_STMT_PREPARE, plen: 45, type: QUERY_TYPE_WRITE|QUERY_TYPE_PREPARE_STMT, stmt: UPDATE sip_buddies_mgw SET  WHERE name=? 
2019-07-09 16:20:54   info   : (5) Session write, routing to all servers.
 
2019-07-09 16:20:54   info   : (5) Route query to master: back1 	[10.10.10.1]:3306
 
2019-07-09 16:20:54   info   : (5) Route query to slave: back2 	[10.10.10.2]:3306
 
2019-07-09 16:20:54   info   : (5) Route query to slave: back3 	[10.10.10.3]:3306
 
2019-07-09 16:20:54   info   : (5) Reply complete, last reply from back1
 
2019-07-09 16:20:54   info   : (5) Session command no. 13 failed: #42000: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near 'WHERE name=?' at line 1
 
2019-07-09 16:20:54   info   : (5) Reply complete, last reply from back3
 
2019-07-09 16:20:54   info   : (5) Reply complete, last reply from back2
 
2019-07-09 16:20:54   info   : (5) > Autocommit: [enabled], trx is [not open], cmd: (0x19) COM_STMT_CLOSE, plen: 9, type: QUERY_TYPE_WRITE, stmt: ID: 0 
2019-07-09 16:20:54   warning: (5) Using unknown prepared statement with ID 0
 
2019-07-09 16:20:54   warning: (5) Closing unknown prepared statement with ID 0

The connector seems to use the statement ID 0 to close a prepared statement that didn't succeed in the first place. Lawrin georg Does this make any sense to you or could it be a problem in Asterisk itself?

Comment by markus makela [ 2019-07-09 ]

gedia Can you get any information about the version string from the Asterisk side? Confirming that MaxScale indeed sends the correct version string would help.

Comment by George Diamantopoulos [ 2019-07-09 ]

Here's the relevant packet captured over the network. Version gets "5.5.5-" prepended as per version_string documentation:

MySQL Protocol
 
    Packet Length: 89
 
    Packet Number: 0
 
    Server Greeting
 
        Protocol: 10
 
        Version: 5.5.5-10.1.14-MariaDB
 
        Thread ID: 9
 
        Salt: e8`i]AM%
 
        Server Capabilities: 0xf7de
 
        Server Language: latin1 COLLATE latin1_swedish_ci (8)
 
        Server Status: 0x0002
 
        Extended Server Capabilities: 0x000f
 
        Authentication Plugin Length: 21
 
        Unused: 00000000000004000000
 
        Salt: +9VB\\c8:\Rh
 
        Authentication Plugin: mysql_native_password

Comment by Lawrin Novitsky [ 2019-07-09 ]

markus makela Now that looks like high chances to be a problem on my side.
gedia What is the C/ODBC version btw? Is it possible to find out?

Comment by Lawrin Novitsky [ 2019-07-09 ]

And what is the server version. The query does not fail with latest MariaDB

Comment by markus makela [ 2019-07-09 ]

It's 10.3.14 and the query does seem like it's missing the field assignment part: UPDATE sip_buddies_mgw SET <field and value should be here> WHERE name=?

Comment by George Diamantopoulos [ 2019-07-09 ]

Installed locally along with asterisk from official mariadb repos for jessie:

ii  libmariadb3:amd64              1:10.3.16+maria~jessie           amd64
 
ii  libmysqlclient18                1:10.3.16+maria~jessie           amd64
 
ii  mariadb-connector-odbc         3.1.1-0.1                        amd64

mariadb-connector-odbc is version 3.1.1 and the package was built locally, which must have pulled libmariadb @ 2c5aebb for compilation. cmake was configured with:

cmake ../mariadb-connector-odbc/ -G "Unix Makefiles" -DCMAKE_BUILD_TYPE=RelWithDebInfo -DCONC_WITH_UNIT_TESTS=Off -DINSTALL_LAYOUT=DEB -DWITH_SSL=OPENSSL -DCMAKE_INSTALL_PREFIX=/usr/ -DWITH_OPENSSL=true -LH

The backends are all on 10.3.16 on debian buster from official mariadb repos.

Comment by Lawrin Novitsky [ 2019-07-15 ]

Would it be possible to provide ODBC trace for the issue? Because I could not repeat the issue. Nor could I find in the source code any possible scenario leading to it.
Asterisk unlikely to be blamed, unless it uses directly MariaDB C API along with ODBC

Comment by George Diamantopoulos [ 2019-07-16 ]

Thanks for the follow-up. I've managed to get a trace, is there any way I can send it to you privately? This is on a development platform of course, but just to be safe that there isn't any privileged information exposed publicly...

I also noticed there's a relevant commit in the 2.3 tree of Maxscale: MXS-2490: Add direct execution support. Are there any nightly builds I can use for testing?

Comment by markus makela [ 2019-07-16 ]

You can find the daily build here: http://max-tst-01.mariadb.com/ci-repository/?C=M;O=D

Comment by George Diamantopoulos [ 2019-07-18 ]

Hm, it seems there are no daily builds for debian. Is the debian source package available somewhere so that I can built my own package for testing? Thanks.

Comment by markus makela [ 2019-07-18 ]

You can find the instructions to build MaxScale from source here: https://github.com/mariadb-corporation/MaxScale/blob/2.3/Documentation/Getting-Started/Building-MaxScale-from-Source-Code.md

Comment by George Diamantopoulos [ 2019-07-24 ]

OK, so I have a few updates. However, please note that these results were produced on systems different than the ones from my previous reports.

Previous reports:

  • Maxscale on debian stretch version 2.3.9 from mariadb official repos
  • mariadb-connector-odbc tag 3.1.1-ga on debian jessie, compiled from source
  • asterisk 11.25.3 on debian jessie, compiled from source

New Test 1:

  • Maxscale on debian stretch, compiled from source at commit 8e23a6cdb96b61fa9231c38538fcc750ac8a93e3 (version string 2.3.10)
  • mariadb-connector-odbc tag 3.1.1-ga on debian buster, compiled from source
  • asterisk 16.4.0 on debian buster, compiled from source

Results: Similar behaviour is seen as with previous reports. Upon starting asterisk, the following was logged. As there didn't seem to be an improvement over the previous setups, I didn't perform any other tests other than starting asterisk.

2019-07-24 16:31:13   warning: (4) Client requests unknown prepared statement ID '6710628' that does not map to an internal ID
 
2019-07-24 16:31:13   warning: (4) Using unknown prepared statement with ID 0
 
2019-07-24 16:31:13   warning: (4) Client requests unknown prepared statement ID '6710628' that does not map to an internal ID
 
2019-07-24 16:31:13   warning: (4) Closing unknown prepared statement with ID 0

New Test 2 - Same configuration as New Test 1 but:

  • mariadb-connector-odbc tag 3.1.2 was compiled from source and used on debian buster (instead of 3.1.1)
  • options use_sql_variables_in=master and max_sescmd_history=1000 were added to readwrite router. These should not affect the "unknown prepared statement" errors in any way, but I'm mentioning this to disclose all changes made

Results: Upon starting asterisk, no errors or warnings are logged this time on the maxscale node. However, the following is logged upon call completion. Despite these warnings in Maxscale logs, functionality does not seem to be affected (calls are setup properly and CDRs are written successfully in MariaDB):

2019-07-24 19:20:38   warning: (4) Client requests unknown prepared statement ID '0' that does not map to an internal ID
 
2019-07-24 19:20:38   warning: (4) Using unknown prepared statement with ID 0
 
2019-07-24 19:20:38   warning: (4) Client requests unknown prepared statement ID '0' that does not map to an internal ID
 
2019-07-24 19:20:38   warning: (4) Closing unknown prepared statement with ID 0
 
2019-07-24 19:20:38   warning: (4) Client requests unknown prepared statement ID '0' that does not map to an internal ID
 
2019-07-24 19:20:38   warning: (4) Using unknown prepared statement with ID 0
 
2019-07-24 19:20:38   warning: (4) Client requests unknown prepared statement ID '0' that does not map to an internal ID
 
2019-07-24 19:20:38   warning: (4) Closing unknown prepared statement with ID 0

Note that this time, only warnings about prepared statements with ID '0' seem to be logged.

Let me know if I can be of any further assistance.

Comment by markus makela [ 2019-07-24 ]

A big thanks for doing all the testing! It looks like the newer versions fix almost all the problems and if I had to guess I'd say the ID 0 issue could possibly be caused by the ODBC connector.

Lawrin what does the ODBC connector use when closing a statement that used the ID -1?

Comment by Lawrin Novitsky [ 2019-07-24 ]

markus makela The thing is that c/odbc does not deal with stmts id directly at all. It uses MariaDB C/C via C API functions. It may be that it erroneously closes stmt handler. But even in this case I am not sure who should handle that - c/c or c/odbc. I don't mind to fix it on my end, though

Comment by George Diamantopoulos [ 2019-08-16 ]

@Lawrin

It seems ODBC connector 3.1.3 behaves the same as 3.1.2 in this regard (case: on buster with asterisk 16). Should I file a bug with the C/Connector project?

Comment by Lawrin Novitsky [ 2019-08-19 ]

gedia Which exactly issue are we talking about here? If about closing of stmt with stmt_id=0, then iirc it wasn't supposed to be in 3.1.3, as the C/C release was finalized by then. Filing the bug won't hurt, but I can do that.
Direct execution(stmtid=-1) with older server versions is supposed to be fixed in c/odbc 3.1.3. But handling of -1 is also supposed to be fixed in the MaxScale, already.
There was execution of malformed query - update with empty set clause. In the trace you provided it appears, that it's not formed by c/odbc, and that is asterisk sends it in this form. It can be the result of incorrect data provided by c/odbc, though. iirc there is error in some catalog function execution, caused by -1 stmtid, right before that 'update' execution. If it persists, then probably bug against c/odbc is needed. Especially if with other drivers it works.

Comment by balyn [ 2019-08-20 ]

Hello. For some reasons, I could not make more diagnostics after mine first post, sorry.
So I returned to my MaxScale server just have updated scaler from 2.3.6 to latest 2.3.11-1.
Also I have updated Linux kernel from 3x to 5x and some libs on all off my servers including scaler server, voip server and master-slave mariadb servers. If it is important.

So now, when I try to connect Asterisk 16.3 with MaxScale 2.3.11-1, I get some new log messages.
Firstly, I wanna show you my maxscale.cnf: https://pastebin.com/LHqcKcP7
As you can see, I try to use readwritesplit here.

As a result, I get this warns+error and no new line in the db:

2019-08-20 13:31:23   warning: (3) The query can't be routed to all backend servers because it includes SELECT and SQL variable modifications which is not supported. Set use_sql_variables_in=master or split the query to two, where SQL variable modifications are done in the first and the SELECT in the second one.
 
2019-08-20 13:31:23   error  : (3) Can't route COM_STMT_EXECUTE:QUERY_TYPE_READ|QUERY_TYPE_USERVAR_WRITE|QUERY_TYPE_USERVAR_READ:"COM_STMT_EXECUTE". SELECT with session data modification is not supported if configuration parameter use_sql_variables_in=all .
 
2019-08-20 13:33:42   warning: (4) Router session exceeded session command history limit. Server reconnection is disabled and only servers with consistent session state are used for the duration ofthe session. To disable this warning and the session command history, add `disable_sescmd_history=true` to service 'splitter'. To increase the limit (currently 50), add `max_sescmd_history` to the same service and increase the value.

After that I put "use_sql_variables_in=master" in [splitter] section, so warns changed and I have new record in the db:

2019-08-20 13:49:48   warning: (5) Router session exceeded session command history limit. Server reconnection is disabled and only servers with consistent session state are used for the duration ofthe session. To disable this warning and the session command history, add `disable_sescmd_history=true` to service 'splitter'. To increase the limit (currently 50), add `max_sescmd_history` to the same service and increase the value.
 
2019-08-20 13:49:50   warning: (4) Client requests unknown prepared statement ID '0' that does not map to an internal ID
 
2019-08-20 13:49:50   warning: (4) Using unknown prepared statement with ID 0
 
2019-08-20 13:49:50   warning: (4) Client requests unknown prepared statement ID '0' that does not map to an internal ID
 
2019-08-20 13:49:50   warning: (4) Closing unknown prepared statement with ID 0

For now, I will make some tests to be sure read-writesplitting works well.

Comment by George Diamantopoulos [ 2019-09-05 ]

@balyn

The warnings you get after having set "use_sql_variables_in=master" do not indicate an issue with Maxscale. It seems that this is an issue with Connector/C which you can follow here: https://jira.mariadb.org/browse/CONC-435

Comment by Diego Dupin [ 2021-01-25 ]

this might be due to https://jira.mariadb.org/browse/CONC-522

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