From 9c28af425e3bb6bf90bd687085ade96e9aeb1af1 Mon Sep 17 00:00:00 2001 From: zotov Date: Mon, 19 Sep 2022 20:05:25 +0300 Subject: [PATCH] Added/Updated bugs\core_1746_test.py. Checked on 3.0.8.33535 (SS/CS), 4.0.1.2692 (SS/CS), 5.0.0.730 (SS/CS) --- tests/bugs/core_1746_test.py | 299 ++++++----------------------------- 1 file changed, 52 insertions(+), 247 deletions(-) diff --git a/tests/bugs/core_1746_test.py b/tests/bugs/core_1746_test.py index 19d7e978..4e8a1b8c 100644 --- a/tests/bugs/core_1746_test.py +++ b/tests/bugs/core_1746_test.py @@ -5,266 +5,71 @@ ID: issue-2170 ISSUE: 2170 TITLE: Expression index can be created while doing inserts into table DESCRIPTION: - We check three cases of Tx setting: WAIT, NO WAIT and LOCK TIMEOUT n. - - First ISQL session always inserts some number of rows and falls in delay (it is created - artificially by attempting to insert duplicate key in index in Tx with lock timeout = 7). - - Second ISQL is launched in SYNC mode after small delay (3 seconds) and starts transaction - with corresponding WAIT/NO WAIT/LOCK TIMEOUT clause. - - If Tx starts with NO wait or lock timeout then this (2nd) ISQL always MUST FAIL. - - After 2nd ISQL will finish, we have to wait yet 5 seconds for 1st ISQL will gone. - Total time of these two delays (3+5=8) must be greater than lock timeout in the script which - is running by 1st ISQL (7 seconds). - - Initial version of this test did use force interruption of both ISQL processes but this was unneeded, - though it helped to discover some other bug in engine which produced bugcheck - see CORE-5275. -NOTES: -[15.1.2022] pcisar - This test may FAIL when run on slow machine (like VM), or fast one (Windows 10 with SSD) JIRA: CORE-1746 FBTEST: bugs.core_1746 +NOTES: + [15.01.2022] pcisar + This test may FAIL when run on slow machine (like VM), or fast one (Windows 10 with SSD) + [19.09.2022] pzotov + Fully reimplemented. Issue described in the ticket can be easy reproduced WITHOUT any concurrent workload. + We can create table with single column and two connections. First of them just inserts one record and + second attempts to create index. + On 2.5.3.26780 and 3.0.0.32483 statement 'create index' will pass (and this must be considered as problem). + On 2.5.27020 and 3.0.1 such attempt leads to exception "-901 / object ... in use" - and this is expected. + See also core_4386_test.py. + + Checked on 3.0.8.33535 (SS/CS), 4.0.1.2692 (SS/CS), 5.0.0.730 (SS/CS) """ import pytest -import time -import subprocess from pathlib import Path + from firebird.qa import * +from firebird.driver import tpb, Isolation -substitutions = [('0: CREATE INDEX LOG: RDB_EXPR_BLOB.*', '0: CREATE INDEX LOG: RDB_EXPR_BLOB'), - ('BULK_INSERT_START.*', 'BULK_INSERT_START'), - ('BULK_INSERT_FINISH.*', 'BULK_INSERT_FINISH'), - ('CREATE_INDX_START.*', 'CREATE_INDX_START'), - ('AFTER LINE.*', 'AFTER LINE')] +db = db_factory(init='create table test(id int);') -init_script = """ - create or alter procedure sp_ins(n int) as begin end; +act = python_act('db') - recreate table test(x int unique using index test_x, s varchar(10) default 'qwerty' ); - - set term ^; - execute block as - begin - execute statement 'drop sequence g'; - when any do begin end - end - ^ - set term ;^ - commit; - create sequence g; - commit; - - set term ^; - create or alter procedure sp_ins(n int) as - begin - while (n>0) do - begin - insert into test( x ) values( gen_id(g,1) ); - n = n - 1; - end - end - ^ - set term ;^ - commit; -""" - -db = db_factory(init=init_script) - -act = python_act('db', substitutions=substitutions) - -tmp_file_bi_in = temp_file('bulk_insert.sql') -tmp_file_bi_out = temp_file('bulk_insert.out') - -expected_stdout = """ - 0: BULK INSERTS LOG: BULK_INSERT_START - 0: BULK INSERTS LOG: BULK_INSERT_FINISH - 0: CREATE INDEX LOG: INSERTS_STATE OK, IS RUNNING - 0: CREATE INDEX LOG: CREATE_INDX_START - 0: CREATE INDEX LOG: SET TRANSACTION WAIT; - 0: CREATE INDEX LOG: CREATE INDEX TEST_WAIT ON TEST COMPUTED BY('WAIT'|| S); - 0: CREATE INDEX LOG: COMMIT; - 0: CREATE INDEX LOG: SET ECHO OFF; - 0: CREATE INDEX LOG: INSERTS_STATE OK, FINISHED - 0: CREATE INDEX LOG: RDB$INDEX_NAME TEST_WAIT - 0: CREATE INDEX LOG: RDB$UNIQUE_FLAG 0 - 0: CREATE INDEX LOG: RDB$INDEX_INACTIVE 0 - 0: CREATE INDEX LOG: RDB_EXPR_BLOB - 0: CREATE INDEX LOG: ('WAIT'|| S) - 0: CREATE INDEX LOG: RECORDS AFFECTED: 1 - 0: CREATE INDEX LOG: SET PLAN ON; - 0: CREATE INDEX LOG: SELECT 1 FROM TEST WHERE 'WAIT'|| S > '' ROWS 0; - 0: CREATE INDEX LOG: PLAN (TEST INDEX (TEST_WAIT)) - 0: CREATE INDEX LOG: SET PLAN OFF; - 0: CREATE INDEX LOG: SET ECHO OFF; - - 1: BULK INSERTS LOG: BULK_INSERT_START - 1: BULK INSERTS LOG: BULK_INSERT_FINISH - 1: CREATE INDEX LOG: INSERTS_STATE OK, IS RUNNING - 1: CREATE INDEX LOG: CREATE_INDX_START - 1: CREATE INDEX LOG: SET TRANSACTION NO WAIT; - 1: CREATE INDEX LOG: CREATE INDEX TEST_NO_WAIT ON TEST COMPUTED BY('NO_WAIT'|| S); - 1: CREATE INDEX LOG: COMMIT; - 1: CREATE INDEX LOG: STATEMENT FAILED, SQLSTATE = 40001 - 1: CREATE INDEX LOG: LOCK CONFLICT ON NO WAIT TRANSACTION - 1: CREATE INDEX LOG: -UNSUCCESSFUL METADATA UPDATE - 1: CREATE INDEX LOG: -OBJECT TABLE "TEST" IS IN USE - - 2: BULK INSERTS LOG: BULK_INSERT_START - 2: BULK INSERTS LOG: BULK_INSERT_FINISH - 2: CREATE INDEX LOG: INSERTS_STATE OK, IS RUNNING - 2: CREATE INDEX LOG: CREATE_INDX_START - 2: CREATE INDEX LOG: SET TRANSACTION LOCK TIMEOUT 1; - 2: CREATE INDEX LOG: CREATE INDEX TEST_LOCK_TIMEOUT_1 ON TEST COMPUTED BY('LOCK_TIMEOUT_1'|| S); - 2: CREATE INDEX LOG: COMMIT; - 2: CREATE INDEX LOG: STATEMENT FAILED, SQLSTATE = 40001 - 2: CREATE INDEX LOG: LOCK TIME-OUT ON WAIT TRANSACTION - 2: CREATE INDEX LOG: -UNSUCCESSFUL METADATA UPDATE - 2: CREATE INDEX LOG: -OBJECT TABLE "TEST" IS IN USE -""" - -@pytest.mark.skip("FIXME: see notes") @pytest.mark.version('>=3') -def test_1(act: Action, tmp_file_bi_in: Path, tmp_file_bi_out: Path, capsys): - rows_to_add = 1000 - tmp_file_bi_in.write_text (f''' - set bail on; - set list on; +def test_1(act: Action, capsys): - -- do NOT use it !! >>> alter sequence g restart with 0; -- gen_id(g,1) will return 0 rather than 1 since 06-aug-2020 on FB 4.x !! + tx_isol_lst = [ Isolation.READ_COMMITTED_NO_RECORD_VERSION, + Isolation.READ_COMMITTED_RECORD_VERSION, + Isolation.SNAPSHOT, + Isolation.SERIALIZABLE, + ] + if act.is_version('>=4'): + tx_isol_lst.append(Isolation.READ_COMMITTED_READ_CONSISTENCY) - delete from test; - set term ^; - execute block as - declare c bigint; - begin - c = gen_id(g, -gen_id(g, 0)); -- restart sequence - end - ^ - set term ;^ - commit; + # for any isolation mode attempt to run DDL for table that is in use by another Tx must fail + # with the same error message. We check all possible Tx isolation modes for that: + for x_isol in tx_isol_lst: + + custom_tpb = tpb(isolation = x_isol, lock_timeout = 0) - set transaction lock timeout 7; -- THIS LOCK TIMEOUT SERVES ONLY FOR DELAY, see below auton Tx start. + with act.db.connect() as con1, act.db.connect() as con2: + tx1 = con1.transaction_manager(custom_tpb) + tx2 = con2.transaction_manager(custom_tpb) + tx1.begin() + tx2.begin() + with tx1.cursor() as cur1, tx2.cursor() as cur2: + try: + cur1.execute( "insert into test(id) values(1)" ) + cur2.execute('create index test_calc_idx on test computed by(id*id)') + tx2.commit() + except Exception as e: + print(e.__str__()) + print(e.gds_codes) - select current_timestamp as bulk_insert_start from rdb$database; - set term ^; - execute block as - declare i int; - begin - execute procedure sp_ins({rows_to_add}); - begin - -- ######################################################### - -- ####################### D E L A Y ##################### - -- ######################################################### - in autonomous transaction do - insert into test( x ) values({rows_to_add}); -- this will cause delay because of duplicate in index - when any do - begin - i = gen_id(g,1); - end - end - end - ^ - set term ;^ - commit; - select current_timestamp as bulk_insert_finish from rdb$database; -''') + expected_fail = """ + lock conflict on no wait transaction + -unsuccessful metadata update + -object TABLE "TEST" is in use + (335544345, 335544351, 335544453) + """ - tx_param = ['WAIT', 'NO WAIT', 'LOCK TIMEOUT 1'] - # - i = 0 - # - for tx_decl in tx_param: - idx_name = tx_decl.replace(' ', '_') - idx_expr = "'" + idx_name + "'|| s" - - sql_create_indx = f''' - set bail on; - set list on; - set blob all; - select - iif( gen_id(g,0) > 0 and gen_id(g,0) < 1 + {rows_to_add}, - 'OK, IS RUNNING', - iif( gen_id(g,0) <=0, - 'WRONG: not yet started, current gen_id='||gen_id(g,0), - 'WRONG: already finished, rows_to_add='|| {rows_to_add} ||', current gen_id='||gen_id(g,0) - ) - ) as inserts_state, - current_timestamp as create_indx_start - from rdb$database; - set autoddl off; - commit; - - set echo on; - set transaction {tx_decl}; - - create index test_{idx_name} on test computed by({idx_expr}); - commit; - set echo off; - - select - iif( gen_id(g,0) >= 1 + {rows_to_add}, - 'OK, FINISHED', - 'SOMETHING WRONG: current gen_id=' || gen_id(g,0)||', rows_to_add='|| {rows_to_add} - ) as inserts_state - from rdb$database; - - set count on; - select - rdb$index_name - ,coalesce(rdb$unique_flag,0) as rdb$unique_flag - ,coalesce(rdb$index_inactive,0) as rdb$index_inactive - ,rdb$expression_source as rdb_expr_blob - from rdb$indices ri - where ri.rdb$index_name = upper( 'test_{idx_name}' ) - ; - set count off; - set echo on; - set plan on; - select 1 from test where {idx_expr} > '' rows 0; - set plan off; - set echo off; - commit; - drop index test_{idx_name}; - commit; -''' - with open(tmp_file_bi_out, mode='w') as f_bulk_insert_log: - # This will insert rows and then stay in pause 10 seconds: - p_bulk_insert = subprocess.Popen([act.vars['isql'], act.db.dsn, - '-user', act.db.user, - '-password', act.db.password, - '-q', '-i', str(tmp_file_bi_in)], - stdout = f_bulk_insert_log, - stderr = subprocess.STDOUT - ) - #act.isql(switches=['-q'], input=sql_bulk_insert) - #bulk_insert_log = act.stdout - # 3.0 Classic: seems that it requires at least 2 seconds for ISQL be loaded into memory. - time.sleep(3) - # This will wait until first ISQL finished - act.expected_stderr = 'DISABLED' - act.isql(switches=['-q', '-n'], input=sql_create_indx) - time.sleep(7) # NB: this delay plus previous (3+5=8) must be GREATER than lock timeout in - - p_bulk_insert.terminate() - bulk_insert_log = tmp_file_bi_out.read_text() - create_indx_log = act.stdout + act.stderr - - log = act.clean_string(bulk_insert_log, act.substitutions) - for line in log.splitlines(): - if line.strip(): - print( str(i)+': BULK INSERTS LOG: '+line.strip().upper() ) - - log = act.clean_string(create_indx_log, act.substitutions) - for line in log.splitlines(): - if line.strip(): - print( str(i)+': CREATE INDEX LOG: '+line.strip().upper() ) - # - i += 1 - # Checks - act.reset() - act.stdout = capsys.readouterr().out - act.expected_stdout = expected_stdout - assert act.clean_stdout == act.clean_expected_stdout + act.expected_stdout = expected_fail + act.stdout = capsys.readouterr().out + assert act.clean_stdout == act.clean_expected_stdout + act.reset()