[MDEV-9367] ExtractValue function doesn't work in stored procedure first few times Created: 2016-01-05  Updated: 2016-03-29  Resolved: 2016-03-29

Status: Closed
Project: MariaDB Server
Component/s: XML Functions
Affects Version/s: 10.0.22, 10.1.9, 10.0, 10.1
Fix Version/s: 5.5.48, 10.0.24, 10.1.13

Type: Bug Priority: Major
Reporter: Estructure Assignee: Oleksandr Byelkin
Resolution: Fixed Votes: 0
Labels: None
Environment:

I have reproduced the bug with 10.0.22 from official repository on debian Jessie ( 10.0.22-0+deb8u1) and 10.1.9 on Windows

Attachments: File test.test     File test_setup.sql    
Issue Links:
Relates
relates to MDEV-9123 Local variable TEXT has mangled data ... Closed
Sprint: 10.2.0-9

 Description   

I have a stored procedure wich process an XML field to get some data. The first few times the procedure is executed it returns NULL or empty string, then it works fine. From HeidiSql, for example, it usually fails two times and then works right, and from ToadSql it fails about four times and then works everytime (the number of failures seems consistent, but could be luck).

The line that seems to be failing is a call to ExtractValue (here with some context):

DECLARE counter INT UNSIGNED DEFAULT 1;
WHILE (counter <= total_count) DO
SELECT ExtractValue(xml, '//service[$counter]/name') INTO service_name;
SET services = CONCAT(services, ',', service_name);
SET counter = counter + 1;
END WHILE;

 Comments   
Comment by Elena Stepanova [ 2016-01-10 ]

Soporte,

Please provide a complete example allowing to reproduce the problem.

  • the full description of the procedure;
  • description and relevant contents of the involved tables;
  • the code or query that you use to call your stored procedure.

Alternatively, you could dissect your code yourself, and extract the actual consequent calls to ExtractValue with already expanded values of xml.

Comment by Estructure [ 2016-01-11 ]

I've attached a file to setup the test environment (creates database, table and stored proc and populates table).

Comment by Estructure [ 2016-01-11 ]

The two first calls to sp_xml_test return NULL, the third one returns the expected result.
I haven't been able to reproduce the issue with direct calls or with smaller data. Removing unused fields (any aa*) below ~10kb seems to change the problem: the first calls return a string with the "delim" string repeated several times, and after a couple calls it just returns the empty string.

I have replaced every character I could with 'a' to avoid encoding problems. The fields used in the XPath are the exception to this, with names like abcd...

The problem goes away if I downgrade the mariadb version to the older debian supported one (10.0.16-1).

Execution results:

> mysql -h myhost -u myuser -p test_db
 
Enter password:
 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
 
Your MariaDB connection id is 4176
 
Server version: 10.0.22-MariaDB-0+deb8u1 (Debian)
 
 
 
Copyright (c) 2000, 2014, Oracle, MariaDB Corporation Ab and others.
 
 
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
 
 
MariaDB [test_db]> CALL sp_test_xml(",", "id");
 
+----------------+
 
| separatedNames |
 
+----------------+
 
| NULL           |
 
+----------------+
 
1 row in set (0.00 sec)
 
 
 
Query OK, 0 rows affected, 1 warning (0.00 sec)
 
 
 
MariaDB [test_db]> CALL sp_test_xml(",", "id");
 
+----------------+
 
| separatedNames |
 
+----------------+
 
| NULL           |
 
+----------------+
 
1 row in set (0.00 sec)
 
 
 
Query OK, 0 rows affected, 1 warning (0.00 sec)
 
 
 
MariaDB [test_db]> CALL sp_test_xml(",", "id");
 
+-------------------------------------------------------------------------------
 
-------+
 
| separatedNames
 
       |
 
+-------------------------------------------------------------------------------
 
-------+
 
| aaaaaaaaaaaaaaaaa,aaaaaaaaaaaaa,aaaaaaaa aaaa,aaaaaaaa aaaaa,aaaaaaaaaaaaaaaaa
 
aaaaa, |
 
+-------------------------------------------------------------------------------
 
-------+
 
1 row in set (0.01 sec)
 
 
 
Query OK, 0 rows affected (0.01 sec)
 
 
 
MariaDB [test_db]>

Comment by Elena Stepanova [ 2016-01-12 ]

Thanks, with the attached data I can reproduce the problem.
In fact, I am also getting bad results with smaller data. The observed results are not entirely deterministic though, sometimes it can be NULL with a warning, as you had, sometimes it's an empty line. With valgrind, the test case produces warnings:

From 10.0 commit 3730d8a225fe33a0157e0aaa85121ef7cecf288d

 
==11998== Invalid read of size 1
 
==11998==    at 0x4C2D350: __GI_memmove (vg_replace_strmem.c:1110)
 
==11998==    by 0x71F1FB: String::copy(String const&) (sql_string.cc:176)
 
==11998==    by 0x9ED8C7: Item_xml_str_func::XML::parse(String*, bool) (item_xmlfunc.cc:2886)
 
==11998==    by 0x9EDE5E: Item_xml_str_func::XML::parse(Item*, bool) (item_xmlfunc.h:67)
 
==11998==    by 0x9EDED6: Item_xml_str_func::get_xml(Item_xml_str_func::XML*, bool) (item_xmlfunc.h:76)
 
==11998==    by 0x9ED2B9: Item_xml_str_func::fix_fields(THD*, Item**) (item_xmlfunc.cc:2693)
 
==11998==    by 0x9AD71B: sp_prepare_func_item(THD*, Item**) (sp_head.cc:375)
 
==11998==    by 0x9AD82A: sp_eval_expr(THD*, Field*, Item**) (sp_head.cc:412)
 
==11998==    by 0x9BA299: sp_rcontext::set_variable(THD*, Field*, Item**) (sp_rcontext.cc:378)
 
==11998==    by 0x65204B: sp_rcontext::set_variable(THD*, unsigned int, Item**) (sp_rcontext.h:201)
 
==11998==    by 0x9B416B: sp_instr_set::exec_core(THD*, unsigned int*) (sp_head.cc:3228)
 
==11998==    by 0x9B37D4: sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*) (sp_head.cc:2971)
 
==11998==    by 0x9B412E: sp_instr_set::execute(THD*, unsigned int*) (sp_head.cc:3221)
 
==11998==    by 0x9AFBA5: sp_head::execute(THD*, bool) (sp_head.cc:1371)
 
==11998==    by 0x9B1851: sp_head::execute_procedure(THD*, List<Item>*) (sp_head.cc:2159)
 
==11998==    by 0x685D6D: mysql_execute_command(THD*) (sql_parse.cc:4731)
 
==11998==  Address 0xd2dc0cf is 143 bytes inside a block of size 11,572 free'd
 
==11998==    at 0x4C283C4: free (vg_replace_malloc.c:474)
 
==11998==    by 0xE69B82: free_memory (safemalloc.c:276)
 
==11998==    by 0xE6980A: sf_realloc (safemalloc.c:184)
 
==11998==    by 0xE589A2: my_realloc (my_malloc.c:164)
 
==11998==    by 0xDE35E7: mi_alloc_rec_buff (mi_open.c:748)
 
==11998==    by 0xDDAF87: mi_reset (mi_extra.c:460)
 
==11998==    by 0xDBA745: ha_myisam::reset() (ha_myisam.cc:1934)
 
==11998==    by 0x87D8BD: handler::ha_reset() (handler.cc:5987)
 
==11998==    by 0x61C4BE: close_thread_table(THD*, TABLE**) (sql_base.cc:1052)
 
==11998==    by 0x61BD07: close_open_tables(THD*) (sql_base.cc:785)
 
==11998==    by 0x61C27F: close_thread_tables(THD*) (sql_base.cc:1009)
 
==11998==    by 0x6873EB: mysql_execute_command(THD*) (sql_parse.cc:5178)
 
==11998==    by 0x9B4083: sp_instr_stmt::exec_core(THD*, unsigned int*) (sp_head.cc:3204)
 
==11998==    by 0x9B37D4: sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*) (sp_head.cc:2971)
 
==11998==    by 0x9B3D8D: sp_instr_stmt::execute(THD*, unsigned int*) (sp_head.cc:3120)
 
==11998==    by 0x9AFBA5: sp_head::execute(THD*, bool) (sp_head.cc:1371)
 
==11998== Invalid read of size 1
 
==11998==    at 0x4C2D35E: __GI_memmove (vg_replace_strmem.c:1110)
 
==11998==    by 0x71F1FB: String::copy(String const&) (sql_string.cc:176)
 
==11998==    by 0x9ED8C7: Item_xml_str_func::XML::parse(String*, bool) (item_xmlfunc.cc:2886)
 
==11998==    by 0x9EDE5E: Item_xml_str_func::XML::parse(Item*, bool) (item_xmlfunc.h:67)
 
==11998==    by 0x9EDED6: Item_xml_str_func::get_xml(Item_xml_str_func::XML*, bool) (item_xmlfunc.h:76)
 
==11998==    by 0x9ED2B9: Item_xml_str_func::fix_fields(THD*, Item**) (item_xmlfunc.cc:2693)
 
==11998==    by 0x9AD71B: sp_prepare_func_item(THD*, Item**) (sp_head.cc:375)
 
==11998==    by 0x9AD82A: sp_eval_expr(THD*, Field*, Item**) (sp_head.cc:412)
 
==11998==    by 0x9BA299: sp_rcontext::set_variable(THD*, Field*, Item**) (sp_rcontext.cc:378)
 
==11998==    by 0x65204B: sp_rcontext::set_variable(THD*, unsigned int, Item**) (sp_rcontext.h:201)
 
==11998==    by 0x9B416B: sp_instr_set::exec_core(THD*, unsigned int*) (sp_head.cc:3228)
 
==11998==    by 0x9B37D4: sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*) (sp_head.cc:2971)
 
==11998==    by 0x9B412E: sp_instr_set::execute(THD*, unsigned int*) (sp_head.cc:3221)
 
==11998==    by 0x9AFBA5: sp_head::execute(THD*, bool) (sp_head.cc:1371)
 
==11998==    by 0x9B1851: sp_head::execute_procedure(THD*, List<Item>*) (sp_head.cc:2159)
 
==11998==    by 0x685D6D: mysql_execute_command(THD*) (sql_parse.cc:4731)
 
==11998==  Address 0xd2dc0d1 is 145 bytes inside a block of size 11,572 free'd
 
==11998==    at 0x4C283C4: free (vg_replace_malloc.c:474)
 
==11998==    by 0xE69B82: free_memory (safemalloc.c:276)
 
==11998==    by 0xE6980A: sf_realloc (safemalloc.c:184)
 
==11998==    by 0xE589A2: my_realloc (my_malloc.c:164)
 
==11998==    by 0xDE35E7: mi_alloc_rec_buff (mi_open.c:748)
 
==11998==    by 0xDDAF87: mi_reset (mi_extra.c:460)
 
==11998==    by 0xDBA745: ha_myisam::reset() (ha_myisam.cc:1934)
 
==11998==    by 0x87D8BD: handler::ha_reset() (handler.cc:5987)
 
==11998==    by 0x61C4BE: close_thread_table(THD*, TABLE**) (sql_base.cc:1052)
 
==11998==    by 0x61BD07: close_open_tables(THD*) (sql_base.cc:785)
 
==11998==    by 0x61C27F: close_thread_tables(THD*) (sql_base.cc:1009)
 
==11998==    by 0x6873EB: mysql_execute_command(THD*) (sql_parse.cc:5178)
 
==11998==    by 0x9B4083: sp_instr_stmt::exec_core(THD*, unsigned int*) (sp_head.cc:3204)
 
==11998==    by 0x9B37D4: sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*) (sp_head.cc:2971)
 
==11998==    by 0x9B3D8D: sp_instr_stmt::execute(THD*, unsigned int*) (sp_head.cc:3120)
 
==11998==    by 0x9AFBA5: sp_head::execute(THD*, bool) (sp_head.cc:1371)

Apparently the problem was introduced by this merge:

commit cfeedbfd3e292f61c7da8f0a7f86307cbeeddb64
 
Merge: bff1af9 16c4b3c
 
Author: Sergei Golubchik <serg@mariadb.org>
 
Date:   Fri Oct 9 17:12:26 2015 +0200
 
 
 
    Merge branch '5.5' into 10.0

It might well be related to MDEV-9123 – this case also depends on the usage of a local TEXT variable (myXml).

I am assigning this to sanja, but sanja, cvicentiu, please make sure you don't duplicate each other's work, it's possible that one fix will fix both issues. Please discuss and feel free to reassign to each other if necessary.

Comment by Oleksandr Byelkin [ 2016-03-28 ]

For me in works as expected:

aaaaa></aaaaaaaaaaaaaa></abcd>');
CALL sp_test_xml(",", "id");
separatedNames
aaaaaaaaaaaaaaaaa,aaaaaaaaaaaaa,aaaaaaaa aaaa,aaaaaaaa aaaaa,aaaaaaaaaaaaaaaaaaaaaa,
CALL sp_test_xml(",", "id");
separatedNames
aaaaaaaaaaaaaaaaa,aaaaaaaaaaaaa,aaaaaaaa aaaa,aaaaaaaa aaaaa,aaaaaaaaaaaaaaaaaaaaaa,
CALL sp_test_xml(",", "id");
separatedNames
aaaaaaaaaaaaaaaaa,aaaaaaaaaaaaa,aaaaaaaa aaaa,aaaaaaaa aaaaa,aaaaaaaaaaaaaaaaaaaaaa,
drop procedure sp_test_xml;
use test;
drop database test_db;
main.test [ pass ] 14

Comment by Elena Stepanova [ 2016-03-29 ]

The problem was fixed in 5.5.48 (and the fix further merged up to 10.0.24, 10.1.13) by the merge from MySQL 5.5, particularly this change:

commit 863f7cebd79e76f90bd8f1e3e0c1a1de5fe77d07
 
Author: Sreeharsha Ramanavarapu <sreeharsha.ramanavarapu@oracle.com>
 
Date:   Fri Jan 8 06:46:59 2016 +0530
 
 
 
    Bug #22232332: SAVING TEXT FIELD TO TEXT VARIABLE IN A
 
                   PROCEDURE RESULTS IN GARBAGE BYTES
 
    
    Issue:
 
    -----
 
    This problem occurs under the following conditions:
 
    
    a) Stored procedure has a variable is declared as TEXT/BLOB.
 
    b) Data is copied into the the variable using the
 
       SELECT...INTO syntax from a TEXT/BLOB column.
 
    
    Data corruption can occur in such cases.
 
    
    SOLUTION:
 
    ---------
 
    The blob type does not allocate space for the string to be
 
    stored. Instead it contains a pointer to the source string.
 
    Since the source is deallocated immediately after the
 
    select statement, this can cause data corruption.
 
    
    As part of the fix for Bug #21143080, when the source was
 
    part of the table's write-set, blob would allocate the
 
    neccessary space. But this fix missed the possibility that,
 
    as in the above case, the target might be a variable.
 
    
    The fix will add the copy_blobs check that was removed by
 
    the earlier fix.

Generated at Thu Feb 08 07:34:08 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.