[MDEV-14857] problem with 10.2.11 server crashing when executing stored procedure Created: 2018-01-02 Updated: 2018-02-19 Resolved: 2018-02-01 |
|
| Status: | Closed |
| Project: | MariaDB Server |
| Component/s: | Stored routines |
| Affects Version/s: | 10.1, 10.2.11, 10.2 |
| Fix Version/s: | 10.1.31, 10.2.13, 10.3.5 |
| Type: | Bug | Priority: | Blocker |
| Reporter: | Nicholas Denning | Assignee: | Oleksandr Byelkin |
| Resolution: | Fixed | Votes: | 6 |
| Labels: | regression | ||
| Environment: |
centos fully patched running java connector 2.1.2 |
||
| Attachments: |
|
||||||||||||||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||||||||||||||
| Sprint: | 10.1.31, 10.2.13 | ||||||||||||||||||||||||||||||||
| Description |
|
Our solution follows a model which maintains most of the database manipulation logic in stored procedures. When I upgraded from 10.2.9 to 10.2.11 I immediately got a failure in existing established code. This code also continues to function on 10.1.28 without problem. I have prepared a database dump and a script which create a repeatable error. to avoid shipping all of the code in the database I cut down the number of procedures shipped to a minimum, and the problem is now occurring in a different procedure so it looks like a general error rather than something that is specific to a partiiuclar error in our code. I dont want to load up the database dump onto a public web site so can I provide that separately when this bug is picked up. I have attached below the server.cnf file, the error log associated with the current repeatable crash plus a couple of other error logs from previous tests, plus the script to generate this problem. To recreate:
the error files below I generated by using first deleting my current error log and then doing a systemctl restart mariadb after loading the database and before running the test script. Also I actually run the test script in Heidi, but I get the same effect whether its hedi or a more complex java app that I am running that normally triggers the problem. Using the 2.1.2 java connector |
| Comments |
| Comment by Elena Stepanova [ 2018-01-02 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
You can upload the dump to ftp.askmonty.org/private. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Nicholas Denning [ 2018-01-02 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Elena, sorry but having a bit of trouble connecting to the ftp site. What precisely do I need to do. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Nicholas Denning [ 2018-01-03 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Have worked it out and uploaded all the above files plus a gzip'ed copy of the sql dump to the ftp site. That file is ip_2018_01_02_togo.sql.zip | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Nicholas Denning [ 2018-01-03 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Incidentally, I have a standard set of .sql build scripts which we run to create all the tables, views, triggers and procedures. After that we have a data load PoJo java application which reads files and loads data in. Its this data load applicaiton which first exhibits the failure. the stack dump I have provided is that java application. when it fails the bug_error and bug_error_2 are generated. To prepare the database dump I first did a standard dump without --events --routines. I then dropped and recreated the database, reloaded from the dump then applied just the procedures that I think are needed for the test procedure to work, so that I dont have to provide the entire data layer code base. The script executing the failing procedure fails in a different procedure from the one running the standalone application and you see that error in the error_mariadb.log In the server.cnf you will see a load of parameters commented out. I was backing out these parameters to see if there was some sort of resource issue, and of course to turn off encryption so that I could export the limited data loaded at this crash point for you in clear. the one difference between normal data load and the test database is that there was about 60MB of data in the DOCUMENT_DATA blob field in DOCUMENT_VERSIONS which I set to null while prepareing the dump to reduce the size of the database to be sent as its not touched by the test procedure. If you get any strange effects and think there are any procedures missing shout and i can upload them. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Nicholas Denning [ 2018-01-03 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The first error logs bug_error and bug_error_2 were generated with the the original server.cnf and the standard java application. You can see different procedures reported being executed and generating the errors. this was only because I was changing the code to try to isolate the problem down to some of my code. However the procedures that were causing the errors work if i ran the application to the point just before the failing stored procedure call, then committed and exited, then ran the procedure directly. However when run within the context of the existing session they result in a crash. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Nicholas Denning [ 2018-01-03 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Sorry, there is a material code difference between the original java application runs that resulted in the bug_error* log files and the error_mariadb version. I realized my coding style was sub-optimal and that i was naming every cursor in the stored procedures CUR1 so i spent some time changing the material cursor names to give them distinct cursor names. That is potentially likely to cause a problem if I have nested cursors using the same name, though the documentation describes how these scenarios are handled so should not have generated a crash, just an error! I may not have completed that task universally. However regardless, this all worked in 10.2.9 and fails in 10.2.11 (my yum update from the repo jumped straight from .9 to .11 so never tested a .10 release). All still works on 10.1.28 as previously mentioned. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Elena Stepanova [ 2018-01-03 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
nick.denning@diegesis.co.uk, thanks a lot for the provided data, analysis and test case, I was able to reproduce the crash as you described. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Nicholas Denning [ 2018-01-04 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Many thanks for the prompt action to verify this. If it can be given a priority that would be very helpful as it is preventing us upgrading to 10.2 in production and as we are using the community edition we cannot start to use the AWS key managment plug in on 10.1. One thing that i forgot to mention was that when I found the first query that was causing this problem and I moved it further up the calling order, it succeeded, so I suspect that this is nothing to do with the specific code but is indeed a resources issues were a resource limit is not being handled correctly. Its strange that this bug hit us immediately - very first run of our application post 10.2.11 upgrade so why has it not also affected other people if it kills us dead. So I also remain suspicious that our use of views in an EXISTS() in stored procedures may have something to do with this. It was a bug in this area that the team fixed early last year for us. That bug generated a very similar type of failure. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Elena Stepanova [ 2018-01-05 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Simplified and obfuscated test case:
Please use it for debugging (and for the test suite if you don't come up with anything better), but after fixing please also make sure to verify the fix on the original full dataset.
Reproducible on 10.1-10.3, recently appeared in 10.1 with this commit:
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Nicholas Denning [ 2018-01-08 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
By the way this is bug has now arrived in 10.1.30 not 10.1.29 as I previously said in this comment.. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Jérôme Brauge [ 2018-01-08 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi, | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Nicholas Denning [ 2018-01-09 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
My test case wasnt small!!!! Elena had by all accounts a huge amount of work to unpick what i sent so rather than me, is the one to be congratulated/thanked. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Nicholas Denning [ 2018-01-09 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Elena and Oleksandr, when you are ready if you want to send me a candidate release for testing I can do that very quickly, 10.1 or 10.2 and probably 10.3 as well. I have a series of VMs and can just snapshot and install on top of those. Nick | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Jérôme Brauge [ 2018-01-10 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi, | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Elena Stepanova [ 2018-01-10 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Given the number of similar complaints and the fact that it's a recent regression, I'm raising it to a Blocker for the next 10.1 (and consequently 10.2) release. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Martin Vit [ 2018-01-10 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
We have the same issue always reproducible on all 10.1.X 10.2.X and 10.3.X versions. We had to roll back 10.2.9 | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Uwe Beierlein [ 2018-01-17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
We have the same issue with version 10.1.30 on | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Lasana Murray [ 2018-01-17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Because of this I had to downgrade (or upgrade) to 10.3.0 which throws strange errors at random but the SPs work. Sadly we probably can't use this in production so technically we do not have a stable MariaDB target we can deploy on since we are making heavy use of JSON. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Widenius [ 2018-01-22 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The crash happens while MariaDB is trying to store an explain of the query: sql/sql_explain.cc:86(Explain_query::get_select(unsigned int))[0x55cba00eddf8] So it's not really related to stored procedures, but to the particulate query used: INSERT INTO ENTITIES_TO_COPY ( ENTITY_UID, ENTITY_TYPE, ENTITY_SUB_TYPE, COPY_INSTANCE_UID ) SELECT ECD.DOCUMENT_VERSION_UID, 'document', 'event', NAME_CONST('V_COPY_INSTANCE_UID',59831) FROM EVENT_COLLECTION_DOCUMENTS ECD JOIN EVENT_DETAILS ED ON ED.EVENT_COLLECTION_UID = ECD.EVENT_COLLECTION_UID WHERE ED.EVENT_UID = NAME_CONST('V_EVENT_UID',34116) AND ED.ORGANISATION_UID = NAME_CONST('V_SOURCE_ORG_UID',26) AND NOT EXISTS ( SELECT * FROM ENTITIES_TO_COPY ETC WHERE ETC.ENTITY_UID = ECD.DOCUMENT_VERSION_UID AND ETC.COPY_INSTANCE_UID = NAME_CONST('V_COPY_INSTANCE_UID',59831) ) | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Oleksandr Byelkin [ 2018-01-23 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
So if it is not SP but EXPLAIN, so I reassign it. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2018-01-24 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Debugging Elena's testcase. Interesting frames in the stack trace of the crash:
The incorrect value of select_lex->select_number comes from the parser:
There, we have
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2018-01-24 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The large value of thd->select_number is not garbage. It comes from sp_head::execute in sp_head.cc:
This was introduced in https://github.com/MariaDB/server/commit/0f43279cc472d82859960f5057e0ec98428459ee . EXPLAIN data structure code expects select_number values to be continuous and small. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Oleksandr Byelkin [ 2018-01-26 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
revision-id: 26dcadf8af745edebbeff44d831380f34d54c3e3 (mariadb-10.1.30-26-g26dcadf8af7)
Counter for select numbering made stored with the statement (before was global) — | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Oleksandr Byelkin [ 2018-01-27 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
revision-id: a0ea3a5822486fa1702d6615f1be30684c3d412f (mariadb-10.1.30-26-ga0ea3a58224)
Counter for select numbering made stored with the statement (before was global) — | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2018-01-31 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Review comments https://lists.launchpad.net/maria-developers/msg11098.html | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Nicholas Denning [ 2018-02-01 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Very interesting to see the development of this fix. We have been having persistent problems over the last year when we referenced VIEWS in queries within an EXISTS() statement in stored procedures. Hopefully this fix will get to the bottom of this fundamental issue. Many thanks. |