[MDEV-24627] MariaDB server crashes when running insert query containing question mark Created: 2021-01-19  Updated: 2022-10-19

Status: Open
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.3.27
Fix Version/s: 10.3

Type: Bug Priority: Major
Reporter: Erik Ellsinger Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 0
Labels: crash
Environment:

CloudLinux release 7.9

Attachments: Text File mysqllog.txt    

 Description   

One of our customers had an error in their PHP code which produced this SQL-query:

INSERT IGNORE INTO transaction (meteringpointid, period_start, period_end, transaction_id, override, date_time) VALUES (('735999114011092315', '202010300000', '202010310000', 'SAPP6S00000000005452236060', 0, '1604185511'), ('735999114011092315', '202010290000', '202010300000', 'SAPP6S00000000005452059211', 0, '1604098690'), ('735999114011092315', '202010280000', '202010290000', 'SAPP6S00000000005451878728', 0, '1604012033'), ('735999114011092315', '202010270000', '202010280000', 'SAPP6S00000000005451690110', 0, '1603923617'), ('735999114011092315', '202010260000', '202010270000', 'SAPP6S00000000005451513362', 0, '1603839133'), ('735999114011092315', '202010250000', '202010260000', 'SAPP6S00000000005451263972', 0, '1603755936'), ('735999114011092315', '202010240000', '202010250000', 'SAPP6S00000000005451004661', 0, '1603668441'), ('735999114011092315', '202010230000', '202010240000', 'SAPP6S00000000005451001234', 0, '1603667326'), ('735999114011092315', '202010220000', '202010230000', 'SAPP6S00000000005450997359', 0, '1603666339'), ('735999114011092315', '202010220000', '202010230000', 'SAPP6S00000000005450683396', 0, '1603491816'), ('735999114011092315', '202010210000', '202010220000', 'SAPP6S00000000005450486980', 0, '1603408274'), ('735999114011092315', '202010200000', '202010210000', 'SAPP6S00000000005450459335', 0, '1603401400'), ('735999114011092315', '202010200000', '202010210000', 'SAPP6S00000000005450241769', 0, '1603315052'), ('735999114011092315', '202010190000', '202010200000', 'SAPP6S00000000005450059914', 0, '1603236026'), ('735999114011092315', '202010180000', '202010190000', 'SAPP6S00000000005450023929', 0, '1603228626'), ('735999114011092315', '202010180000', '202010190000', 'SAPP6S00000000005449815178', 0, '1603144250'), ('735999114011092315', '202010170000', '202010180000', 'SAPP6S00000000005449597207', 0, '1603057673'), ('735999114011092315', '202010160000', '202010170000', 'SAPP6S00000000005449446816', 0, '1602986533'), ('735999114011092315', '202010140000', '202010150000', 'SAPP6S00000000005449197042', 0, '1602981499'), ('735999114011092315', '202010150000', '202010160000', 'SAPP6S00000000005449400609', 0, '1602981010'), ('735999114011092315', '202010140000', '202010150000', 'SAPP6S00000000005448994277', 0, '1602796268'), ('735999114011092315', '202010130000', '202010140000', 'SAPP6S00000000005448779974', 0, '1602709915'), ('735999114011092315', '202010120000', '202010130000', 'SAPP6S00000000005448573693', 0, '1602625352'), ('735999114011092315', '202010110000', '202010120000', 'SAPP6S00000000005448348932', 0, '1602538932'), ('735999114011092315', '202010100000', '202010110000', 'SAPP6S00000000005448166218', 0, '1602457852'), ('735999114011092315', '202010090000', '202010100000', 'SAPP6S00000000005448137072', 0, '1602450688'), ('735999114011092315', '202010090000', '202010100000', 'SAPP6S00000000005447946713', 0, '1602366344'), ('735999114011092315', '202010080000', '202010090000', 'SAPP6S00000000005447743476', 0, '1602277635'), ('735999114011092315', '202010070000', '202010080000', 'SAPP6S00000000005447563496', 0, '1602199243'), ('735999114011092315', '202010060000', '202010070000', 'SAPP6S00000000005447526995', 0, '1602191206'), ('735999114011092315', '202010060000', '202010070000', 'SAPP6S00000000005447304415', 0, '1602105219'), ('735999114011092315', '202010050000', '202010060000', 'SAPP6S00000000005447112248', 0, '1602025352'), ('735999114011092315', '202010040000', '202010050000', 'SAPP6S00000000005447084790', 0, '1602018735'), ('735999114011092315', '202010040000', '202010050000', 'SAPP6S00000000005446861286', 0, '1601932290'), ('735999114011092315', '202010030000', '202010040000', 'SAPP6S00000000005446654736', 0, '1601853071'), ('735999114011092315', '202010020000', '202010030000', 'SAPP6S00000000005446628360', 0, '1601846026'), ('735999114011092315', '202010020000', '202010030000', 'SAPP6S00000000005446433656', 0, '1601767244'), ('735999114011092315', '202010010000', '202010020000', 'SAPP6S00000000005446409159', 0, '1601762046'), ('735999114011092315', '202009300000', '202010010000', 'SAPP6S00000000005446046795', 0, '1601676997'), ('735999114011092315', '202010010000', '202010020000', 'SAPP6S00000000005446046814', 0, '1601676996'), ('735999114011092315', '202009300000', '202010010000', 'SAPP6S00000000005445623907', 0, '1601588099'), ?, ?, ?, ?, ?)

Running that query caused the MariaDB server to crash, it then went into a restart loop since cPanel tried to automatically restart MariaDB but it just kept crashing since the customer application was still running. When the customer fixed their code the problem stopped and the query now looks like this:

INSERT IGNORE INTO transaction (meteringpointid, period_start, period_end, transaction_id, override, date_time) VALUES ('735999114011092315', '202010300000', '202010310000', 'SAPP6S00000000005452236060', 0, '1604185511'), ('735999114011092315', '202010290000', '202010300000', 'SAPP6S00000000005452059211', 0, '1604098690'), ('735999114011092315', '202010280000', '202010290000', 'SAPP6S00000000005451878728', 0, '1604012033'), ('735999114011092315', '202010270000', '202010280000', 'SAPP6S00000000005451690110', 0, '1603923617'), ('735999114011092315', '202010260000', '202010270000', 'SAPP6S00000000005451513362', 0, '1603839133'), ('735999114011092315', '202010250000', '202010260000', 'SAPP6S00000000005451263972', 0, '1603755936'), ('735999114011092315', '202010240000', '202010250000', 'SAPP6S00000000005451004661', 0, '1603668441'), ('735999114011092315', '202010230000', '202010240000', 'SAPP6S00000000005451001234', 0, '1603667326'), ('735999114011092315', '202010220000', '202010230000', 'SAPP6S00000000005450997359', 0, '1603666339'), ('735999114011092315', '202010220000', '202010230000', 'SAPP6S00000000005450683396', 0, '1603491816'), ('735999114011092315', '202010210000', '202010220000', 'SAPP6S00000000005450486980', 0, '1603408274'), ('735999114011092315', '202010200000', '202010210000', 'SAPP6S00000000005450459335', 0, '1603401400'), ('735999114011092315', '202010200000', '202010210000', 'SAPP6S00000000005450241769', 0, '1603315052'), ('735999114011092315', '202010190000', '202010200000', 'SAPP6S00000000005450059914', 0, '1603236026'), ('735999114011092315', '202010180000', '202010190000', 'SAPP6S00000000005450023929', 0, '1603228626'), ('735999114011092315', '202010180000', '202010190000', 'SAPP6S00000000005449815178', 0, '1603144250'), ('735999114011092315', '202010170000', '202010180000', 'SAPP6S00000000005449597207', 0, '1603057673'), ('735999114011092315', '202010160000', '202010170000', 'SAPP6S00000000005449446816', 0, '1602986533'), ('735999114011092315', '202010140000', '202010150000', 'SAPP6S00000000005449197042', 0, '1602981499'), ('735999114011092315', '202010150000', '202010160000', 'SAPP6S00000000005449400609', 0, '1602981010'), ('735999114011092315', '202010140000', '202010150000', 'SAPP6S00000000005448994277', 0, '1602796268'), ('735999114011092315', '202010130000', '202010140000', 'SAPP6S00000000005448779974', 0, '1602709915'), ('735999114011092315', '202010120000', '202010130000', 'SAPP6S00000000005448573693', 0, '1602625352'), ('735999114011092315', '202010110000', '202010120000', 'SAPP6S00000000005448348932', 0, '1602538932'), ('735999114011092315', '202010100000', '202010110000', 'SAPP6S00000000005448166218', 0, '1602457852'), ('735999114011092315', '202010090000', '202010100000', 'SAPP6S00000000005448137072', 0, '1602450688'), ('735999114011092315', '202010090000', '202010100000', 'SAPP6S00000000005447946713', 0, '1602366344'), ('735999114011092315', '202010080000', '202010090000', 'SAPP6S00000000005447743476', 0, '1602277635'), ('735999114011092315', '202010070000', '202010080000', 'SAPP6S00000000005447563496', 0, '1602199243'), ('735999114011092315', '202010060000', '202010070000', 'SAPP6S00000000005447526995', 0, '1602191206'), ('735999114011092315', '202010060000', '202010070000', 'SAPP6S00000000005447304415', 0, '1602105219'), ('735999114011092315', '202010050000', '202010060000', 'SAPP6S00000000005447112248', 0, '1602025352'), ('735999114011092315', '202010040000', '202010050000', 'SAPP6S00000000005447084790', 0, '1602018735'), ('735999114011092315', '202010040000', '202010050000', 'SAPP6S00000000005446861286', 0, '1601932290'), ('735999114011092315', '202010030000', '202010040000', 'SAPP6S00000000005446654736', 0, '1601853071'), ('735999114011092315', '202010020000', '202010030000', 'SAPP6S00000000005446628360', 0, '1601846026'), ('735999114011092315', '202010020000', '202010030000', 'SAPP6S00000000005446433656', 0, '1601767244'), ('735999114011092315', '202010010000', '202010020000', 'SAPP6S00000000005446409159', 0, '1601762046'), ('735999114011092315', '202009300000', '202010010000', 'SAPP6S00000000005446046795', 0, '1601676997'), ('735999114011092315', '202010010000', '202010020000', 'SAPP6S00000000005446046814', 0, '1601676996'), ('735999114011092315', '202009300000', '202010010000', 'SAPP6S00000000005445623907', 0, '1601588099')

Notice the question marks at the end of the first query, once they were replaced with real data the server stopped crashing which makes me think MariaDB crashed because of the above invalid query.

I have attached part of the mysql-log, it just loops the same thing over and over again since the server keep restarting.

 Comments   
Comment by Elena Stepanova [ 2021-01-31 ]

Could you please paste or attach your config files and paste the output of SHOW CREATE TABLE transaction?
Do you happen to have the general log (SQL log) from any of the occurrences, or maybe a coredump left since then?

Comment by Erik Ellsinger [ 2021-02-01 ]

I have a test environment where I can recreate the issue so I have created logs and core dumps for you. Uploaded a zip file with it to your private FTP, filename MDEV-24627.zip.

Comment by Elena Stepanova [ 2021-02-01 ]

Thanks. Could you please also upload there the mysqld binary with which the coredumps were created?
Or better yet, can you paste or upload the php code which produced the faulty statement ("prepare", "bind", "execute" commands and the value assignments)?

Comment by Erik Ellsinger [ 2021-02-11 ]

Been looking at this some more, tcpdumped the traffic to MariaDB when it was crashing and caught the query that caused it, I uploaded it to your FTP, file out2.pcap.

Comment by Erik Ellsinger [ 2021-03-08 ]

Have you had any time to look into this more?

Comment by Erik Ellsinger [ 2021-05-11 ]

Could anyone give an update on the status here? Maybe @Oleksandr Byelkin

I saw that you added 10.3 as Fix version, does that mean you have been able to verify the bug?

Comment by Elena Stepanova [ 2021-05-23 ]

Hi,

I saw that you added 10.3 as Fix version, does that mean you have been able to verify the bug?

No, I haven't. I created a js script which produces a seemingly identical statement, but it doesn't cause a server crash.
It is not very surprising though, because there are many factors still unknown.
The way the uploaded js code connects to the database and executes a prepared statement is obfuscated through calls to other custom modules which we don't have access to, so it remains unclear which standard/third-party modules it uses underneath (or none at all, and the application uses its own implementation of server-side prepared statements).
The server binary is a custom build, not produced by MariaDB, so we don't know how it was built and whether it is important.
And we can't get the stack trace either, because without the binary and system libraries the coredumps are unusable.

10.3 in the fix version is at this point a technicality for JIRA handling. The report has been assigned to Oleksandr Byelkin in case he has seen something like this before and can make an educated guess what the problem may be. I am not very optimistic however – without either a piece of code which reproduces it or at least a resolved stack trace there is very little chance for a progress.

Comment by Erik Ellsinger [ 2021-05-24 ]

Went back to see if I could find the information you need. Found this:

services/kbisService.js:const db = require('../util/database')

Content of that file:

const mysql = require('mysql2');
 
const config  = require('../config')
 
 
 
const pool = mysql.createPool({
 
    host: config.db.host,
 
    user: config.db.user,
 
    database: config.db.database,
 
    password: config.db.password,
 
    debug: true
 
});
 
 
 
module.exports = pool.promise();

So it seems like they are using this: https://www.npmjs.com/package/mysql2

I also did try to reproduce the issue again to make sure it's still there and it is. I have uploaded a new coredump and the MySQL binary to your private FTP, file names:

coredumps.MDEV-24627.zip
mysql.MDEV-24627

Comment by Elena Stepanova [ 2021-05-24 ]

Thanks. However, the binary you have uploaded is not MariaDB server, but MariaDB client. The coredumps were created by /usr/sbin/mysqld.

Comment by Erik Ellsinger [ 2021-05-24 ]

Sorry, my mistake. I have uploaded a new file now: mysqld.MDEV-24627

Comment by Elena Stepanova [ 2021-05-24 ]

Thanks.

Stack trace from a coredump:

#2  <signal handler called>
 
#3  0x00005604040b26df in append_query_string(charset_info_st const*, String*, char const*, unsigned long, bool) ()
 
#4  0x0000560403fdae36 in Item_param::value_query_val_str(THD*, String*) const ()
 
#5  0x0000560403fdb248 in Item_param::append_for_log(THD*, String*) ()
 
#6  0x0000560403deaf08 in insert_params_with_log(Prepared_statement*, unsigned char*, unsigned char*, unsigned char*, String*) ()
 
#7  0x0000560403def538 in Prepared_statement::set_parameters(String*, unsigned char*, unsigned char*) ()
 
#8  0x0000560403df0625 in Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*) ()
 
#9  0x0000560403df139f in mysql_stmt_execute_common(THD*, unsigned long, unsigned char*, unsigned char*, unsigned long, bool, bool) ()
 
#10 0x0000560403df147d in mysqld_stmt_execute(THD*, char*, unsigned int) ()
 
#11 0x0000560403ddf729 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) ()
 
#12 0x0000560403de150b in do_command(THD*) ()
 
#13 0x0000560403eb8846 in do_handle_one_connection(CONNECT*) ()
 
#14 0x0000560403eb895d in handle_one_connection ()
 
#15 0x00007f966d4ddea5 in start_thread () from /lib64/libpthread.so.0
 
#16 0x00007f966b87d9fd in ?? () from /lib64/libc.so.6
 
#17 0x0000000000000000 in ?? ()

Comment by Erik Ellsinger [ 2021-05-24 ]

You need anything else from me?

Comment by Elena Stepanova [ 2021-05-24 ]

If can you reproduce it easily, could you maybe check whether the crash stops happening if you turn off general_log (SET GLOBAL general_log=off or general_log=0 in the config file)?

Comment by Erik Ellsinger [ 2021-06-01 ]

Tried it and yes it does still crash.

Comment by Roel Van de Paar [ 2021-11-18 ]

Note that the crashing query is misformed. It tries to insert into 6 columns, in this way (pseudo code):

INSERT IGNORE ...6 cols listed... VALUES ((c1,c2,c3,c4,c5,c6),(c1,c2,c3,c4,c5,c6),?,?,?,?,?);   # Note; nesting and 5 question marks

Manually testing this with a simple table definition does not crash.

Comment by Roel Van de Paar [ 2021-11-18 ]

Also note that the '?' may just be a rendering, not the actual crashing query.

Comment by Erik Ellsinger [ 2022-01-10 ]

We upgraded to MariaDB 10.5 now so could test it on this version as well and I ran into the same issue.

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