2 @message |
assert
MON$CRYPT_STATE 3
DROP DATABASE;
- Statement failed, SQLSTATE = 42000
+ Statement failed, SQLSTATE = 40001
- unsuccessful metadata update
+ lock time-out on wait transaction
-object is in use
set echo off;
DB_NAME /var/tmp/qa_2024/test_11480/tmp_gh_7200.tmp.fdb
LOG DETAILS:
2025-02-20 04:57:31.082
2025-02-20 04:57:31.091 act = <firebird.qa.plugin.Action object at [hex]>
2025-02-20 04:57:31.104 act_tmp = <firebird.qa.plugin.Action object at [hex]>
2025-02-20 04:57:31.112 tmp_sql = PosixPath('/var/tmp/qa_2024/test_11480/tmp_gh_7200.tmp.sql')
2025-02-20 04:57:31.119 tmp_log = PosixPath('/var/tmp/qa_2024/test_11480/tmp_gh_7200.tmp.log')
2025-02-20 04:57:31.125 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-02-20 04:57:31.132
2025-02-20 04:57:31.137 @pytest.mark.encryption
2025-02-20 04:57:31.144 @pytest.mark.version('>=4.0.2')
2025-02-20 04:57:31.151 def test_1(act: Action, act_tmp: Action, tmp_sql: Path, tmp_log: Path, capsys):
2025-02-20 04:57:31.158
2025-02-20 04:57:31.164 init_sql = f"""
2025-02-20 04:57:31.170 recreate table test(s varchar({FLD_LEN}));
2025-02-20 04:57:31.177 commit;
2025-02-20 04:57:31.183 set term ^;
2025-02-20 04:57:31.190 execute block as
2025-02-20 04:57:31.196 declare n int = {N_ROWS};
2025-02-20 04:57:31.202 begin
2025-02-20 04:57:31.208 while (n>0) do
2025-02-20 04:57:31.215 begin
2025-02-20 04:57:31.221 insert into test(s) values(lpad('', {FLD_LEN}, uuid_to_char(gen_uuid())));
2025-02-20 04:57:31.228 n = n - 1;
2025-02-20 04:57:31.234 end
2025-02-20 04:57:31.240 end
2025-02-20 04:57:31.246 ^
2025-02-20 04:57:31.252 -- for debug, trace must be started with log_proc = true:
2025-02-20 04:57:31.258 create procedure sp_debug (a_point varchar(50)) as
2025-02-20 04:57:31.265 begin
2025-02-20 04:57:31.271 -- nop --
2025-02-20 04:57:31.278 end
2025-02-20 04:57:31.286 ^
2025-02-20 04:57:31.295 set term ;^
2025-02-20 04:57:31.304 commit;
2025-02-20 04:57:31.312 create index test_s on test(s);
2025-02-20 04:57:31.321 """
2025-02-20 04:57:31.330 act_tmp.isql(switches=['-q'], input = init_sql, combine_output = True)
2025-02-20 04:57:31.338 assert act_tmp.clean_stdout == ''
2025-02-20 04:57:31.347 act_tmp.reset()
2025-02-20 04:57:31.356
2025-02-20 04:57:31.364 #############################################
2025-02-20 04:57:31.373 ### c h a n g e F W t o O N ###
2025-02-20 04:57:31.381 #############################################
2025-02-20 04:57:31.390 act_tmp.db.set_sync_write()
2025-02-20 04:57:31.398
2025-02-20 04:57:31.406
2025-02-20 04:57:31.413 # QA_GLOBALS -- dict, is defined in qa/plugin.py, obtain settings
2025-02-20 04:57:31.422 # from act.files_dir/'test_config.ini':
2025-02-20 04:57:31.430 enc_settings = QA_GLOBALS['encryption']
2025-02-20 04:57:31.438
2025-02-20 04:57:31.447 encryption_plugin = enc_settings['encryption_plugin'] # fbSampleDbCrypt
2025-02-20 04:57:31.455 encryption_holder = enc_settings['encryption_holder'] # fbSampleKeyHolder
2025-02-20 04:57:31.463 encryption_key = enc_settings['encryption_key'] # Red
2025-02-20 04:57:31.472
2025-02-20 04:57:31.480 sttm = f'alter database encrypt with "{encryption_plugin}" key "{encryption_key}";'
2025-02-20 04:57:31.489 tmp_sql.write_bytes(sttm.encode('utf-8'))
2025-02-20 04:57:31.497
2025-02-20 04:57:31.505 with tmp_log.open('w') as f_log:
2025-02-20 04:57:31.513
2025-02-20 04:57:31.521 p = subprocess.Popen( [ act_tmp.vars['isql'],
2025-02-20 04:57:31.530 '-q',
2025-02-20 04:57:31.539 '-user', act_tmp.db.user,
2025-02-20 04:57:31.548 '-password', act_tmp.db.password,
2025-02-20 04:57:31.557 act_tmp.db.dsn,
2025-02-20 04:57:31.566 '-i', tmp_sql
2025-02-20 04:57:31.573 ],
2025-02-20 04:57:31.582 stdout = f_log, stderr = subprocess.STDOUT
2025-02-20 04:57:31.589 )
2025-02-20 04:57:31.597
2025-02-20 04:57:31.605 encryption_started = False
2025-02-20 04:57:31.613 with act_tmp.db.connect() as con_watcher:
2025-02-20 04:57:31.621
2025-02-20 04:57:31.628 ps, rs = None, None
2025-02-20 04:57:31.635 try:
2025-02-20 04:57:31.642 custom_tpb = tpb(isolation = Isolation.SNAPSHOT, lock_timeout = -1)
2025-02-20 04:57:31.650 tx_watcher = con_watcher.transaction_manager(custom_tpb)
2025-02-20 04:57:31.657 cur_watcher = tx_watcher.cursor()
2025-02-20 04:57:31.664
2025-02-20 04:57:31.672 # 0 = non-encrypted; 1 = encrypted; 2 = is DEcrypting; 3 - is Encrypting
2025-02-20 04:57:31.680 ps = cur_watcher.prepare('select mon$crypt_state from mon$database')
2025-02-20 04:57:31.688
2025-02-20 04:57:31.696 i = 0
2025-02-20 04:57:31.703 da = dt.now()
2025-02-20 04:57:31.711 while True:
2025-02-20 04:57:31.719 # ::: NB ::: 'ps' returns data, i.e. this is SELECTABLE expression.
2025-02-20 04:57:31.728 # We have to store result of cur.execute(<psInstance>) in order to
2025-02-20 04:57:31.736 # close it explicitly.
2025-02-20 04:57:31.743 # Otherwise AV can occur during Python garbage collection and this
2025-02-20 04:57:31.751 # causes pytest to hang on its final point.
2025-02-20 04:57:31.760 # Explained by hvlad, email 26.10.24 17:42
2025-02-20 04:57:31.768 rs = cur_watcher.execute(ps)
2025-02-20 04:57:31.776 for r in rs:
2025-02-20 04:57:31.785 db_crypt_state = r[0]
2025-02-20 04:57:31.791
2025-02-20 04:57:31.799 tx_watcher.commit()
2025-02-20 04:57:31.807 db = dt.now()
2025-02-20 04:57:31.819 diff_ms = (db-da).seconds*1000 + (db-da).microseconds//1000
2025-02-20 04:57:31.830 if db_crypt_state == IS_ENCRYPTING_STATE:
2025-02-20 04:57:31.843 encryption_started = True
2025-02-20 04:57:31.852 cur_watcher.call_procedure('sp_debug', ('encryption_started',))
2025-02-20 04:57:31.860 break
2025-02-20 04:57:31.866 elif diff_ms > MAX_WAIT_FOR_ENCRYPTION_START_MS:
2025-02-20 04:57:31.873 break
2025-02-20 04:57:31.878 time.sleep(0.1)
2025-02-20 04:57:31.883
2025-02-20 04:57:31.888 except DatabaseError as e:
2025-02-20 04:57:31.893 print( e.__str__() )
2025-02-20 04:57:31.899 print(e.gds_codes)
2025-02-20 04:57:31.905 finally:
2025-02-20 04:57:31.910 if rs:
2025-02-20 04:57:31.920 rs.close() # <<< EXPLICITLY CLOSING CURSOR RESULTS
2025-02-20 04:57:31.928 if ps:
2025-02-20 04:57:31.939 ps.free()
2025-02-20 04:57:31.952
2025-02-20 04:57:31.962 assert encryption_started, f'Could not find start of encryption process for {MAX_WAIT_FOR_ENCRYPTION_START_MS} ms.'
2025-02-20 04:57:31.970
2025-02-20 04:57:31.978 #-----------------------------------------------------------------
2025-02-20 04:57:31.985
2025-02-20 04:57:31.991 drop_db_when_running_encryption_sql = f"""
2025-02-20 04:57:31.998 set list on;
2025-02-20 04:57:32.005 select mon$crypt_state from mon$database;
2025-02-20 04:57:32.011 commit;
2025-02-20 04:57:32.019 set echo on;
2025-02-20 04:57:32.027 DROP DATABASE;
2025-02-20 04:57:32.035 set echo off;
2025-02-20 04:57:32.043 select lower(rdb$get_context('SYSTEM', 'DB_NAME')) as db_name from rdb$database;
2025-02-20 04:57:32.053 """
2025-02-20 04:57:32.060 tmp_sql.write_text(drop_db_when_running_encryption_sql)
2025-02-20 04:57:32.066
2025-02-20 04:57:32.077 drop_db_expected_stdout = f"""
2025-02-20 04:57:32.088 MON$CRYPT_STATE {IS_ENCRYPTING_STATE}
2025-02-20 04:57:32.097 DROP DATABASE;
2025-02-20 04:57:32.112 Statement failed, SQLSTATE = 42000
2025-02-20 04:57:32.125 unsuccessful metadata update
2025-02-20 04:57:32.135 -object is in use
2025-02-20 04:57:32.144 set echo off;
2025-02-20 04:57:32.157 DB_NAME {str(act_tmp.db.db_path).lower()}
2025-02-20 04:57:32.170 """
2025-02-20 04:57:32.181
2025-02-20 04:57:32.196 act_tmp.expected_stdout = drop_db_expected_stdout
2025-02-20 04:57:32.205
2025-02-20 04:57:32.216 # Get current state of encryption (again, just for additional check)
2025-02-20 04:57:32.228 # and attempt to DROP database:
2025-02-20 04:57:32.235 ###############################
2025-02-20 04:57:32.241 act_tmp.isql(switches=['-q', '-n'], input_file = tmp_sql, combine_output=True)
2025-02-20 04:57:32.249
2025-02-20 04:57:32.262 # If following assert fails then act_tmp.db.db_path was unexpectedly removed from disk:
2025-02-20 04:57:32.278 > assert act_tmp.clean_stdout == act_tmp.clean_expected_stdout
2025-02-20 04:57:32.288 E assert
2025-02-20 04:57:32.297 E MON$CRYPT_STATE 3
2025-02-20 04:57:32.307 E DROP DATABASE;
2025-02-20 04:57:32.315 E - Statement failed, SQLSTATE = 42000
2025-02-20 04:57:32.327 E + Statement failed, SQLSTATE = 40001
2025-02-20 04:57:32.341 E - unsuccessful metadata update
2025-02-20 04:57:32.351 E + lock time-out on wait transaction
2025-02-20 04:57:32.361 E -object is in use
2025-02-20 04:57:32.368 E set echo off;
2025-02-20 04:57:32.374 E DB_NAME /var/tmp/qa_2024/test_11480/tmp_gh_7200.tmp.fdb
2025-02-20 04:57:32.382
2025-02-20 04:57:32.391 tests/bugs/gh_7200_test.py:214: AssertionError
2025-02-20 04:57:32.400 ---------------------------- Captured stdout setup -----------------------------
2025-02-20 04:57:32.411 Creating db: localhost:/var/tmp/qa_2024/test_11480/test.fdb [page_size=16384, sql_dialect=None, charset='NONE', user=SYSDBA, password=masterkey]
2025-02-20 04:57:32.423 Creating db: localhost:/var/tmp/qa_2024/test_11480/tmp_gh_7200.tmp.fdb [page_size=None, sql_dialect=None, charset='NONE', user=SYSDBA, password=masterkey]
|
3 #text |
act = <firebird.qa.plugin.Action pytest object at [hex]>
act_tmp = <firebird.qa.plugin.Action pytest object at [hex]>
tmp_sql = PosixPath('/var/tmp/qa_2024/test_11480/tmp_gh_7200.tmp.sql')
tmp_log = PosixPath('/var/tmp/qa_2024/test_11480/tmp_gh_7200.tmp.log')
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>
@pytest.mark.encryption
@pytest.mark.version('>=4.0.2')
def test_1(act: Action, act_tmp: Action, tmp_sql: Path, tmp_log: Path, capsys):
init_sql = f"""
recreate table test(s varchar({FLD_LEN}));
commit;
set term ^;
execute block as
declare n int = {N_ROWS};
begin
while (n>0) do
begin
insert into test(s) values(lpad('', {FLD_LEN}, uuid_to_char(gen_uuid())));
n = n - 1;
end
end
^
-- for debug, trace must be started with log_proc = true:
create procedure sp_debug (a_point varchar(50)) as
begin
-- nop --
end
^
set term ;^
commit;
create index test_s on test(s);
"""
act_tmp.isql(switches=['-q'], input = init_sql, combine_output = True)
assert act_tmp.clean_stdout == ''
act_tmp.reset()
#############################################
### c h a n g e F W t o O N ###
#############################################
act_tmp.db.set_sync_write()
# QA_GLOBALS -- dict, is defined in qa/plugin.py, obtain settings
# from act.files_dir/'test_config.ini':
enc_settings = QA_GLOBALS['encryption']
encryption_plugin = enc_settings['encryption_plugin'] # fbSampleDbCrypt
encryption_holder = enc_settings['encryption_holder'] # fbSampleKeyHolder
encryption_key = enc_settings['encryption_key'] # Red
sttm = f'alter database encrypt with "{encryption_plugin}" key "{encryption_key}";'
tmp_sql.write_bytes(sttm.encode('utf-8'))
with tmp_log.open('w') as f_log:
p = subprocess.Popen( [ act_tmp.vars['isql'],
'-q',
'-user', act_tmp.db.user,
'-password', act_tmp.db.password,
act_tmp.db.dsn,
'-i', tmp_sql
],
stdout = f_log, stderr = subprocess.STDOUT
)
encryption_started = False
with act_tmp.db.connect() as con_watcher:
ps, rs = None, None
try:
custom_tpb = tpb(isolation = Isolation.SNAPSHOT, lock_timeout = -1)
tx_watcher = con_watcher.transaction_manager(custom_tpb)
cur_watcher = tx_watcher.cursor()
# 0 = non-encrypted; 1 = encrypted; 2 = is DEcrypting; 3 - is Encrypting
ps = cur_watcher.prepare('select mon$crypt_state from mon$database')
i = 0
da = dt.now()
while True:
# ::: NB ::: 'ps' returns data, i.e. this is SELECTABLE expression.
# We have to store result of cur.execute(<psInstance>) in order to
# close it explicitly.
# Otherwise AV can occur during Python garbage collection and this
# causes pytest to hang on its final point.
# Explained by hvlad, email 26.10.24 17:42
rs = cur_watcher.execute(ps)
for r in rs:
db_crypt_state = r[0]
tx_watcher.commit()
db = dt.now()
diff_ms = (db-da).seconds*1000 + (db-da).microseconds//1000
if db_crypt_state == IS_ENCRYPTING_STATE:
encryption_started = True
cur_watcher.call_procedure('sp_debug', ('encryption_started',))
break
elif diff_ms > MAX_WAIT_FOR_ENCRYPTION_START_MS:
break
time.sleep(0.1)
except DatabaseError as e:
print( e.__str__() )
print(e.gds_codes)
finally:
if rs:
rs.close() # <<< EXPLICITLY CLOSING CURSOR RESULTS
if ps:
ps.free()
assert encryption_started, f'Could not find start of encryption process for {MAX_WAIT_FOR_ENCRYPTION_START_MS} ms.'
#-----------------------------------------------------------------
drop_db_when_running_encryption_sql = f"""
set list on;
select mon$crypt_state from mon$database;
commit;
set echo on;
DROP DATABASE;
set echo off;
select lower(rdb$get_context('SYSTEM', 'DB_NAME')) as db_name from rdb$database;
"""
tmp_sql.write_text(drop_db_when_running_encryption_sql)
drop_db_expected_stdout = f"""
MON$CRYPT_STATE {IS_ENCRYPTING_STATE}
DROP DATABASE;
Statement failed, SQLSTATE = 42000
unsuccessful metadata update
-object is in use
set echo off;
DB_NAME {str(act_tmp.db.db_path).lower()}
"""
act_tmp.expected_stdout = drop_db_expected_stdout
# Get current state of encryption (again, just for additional check)
# and attempt to DROP database:
###############################
act_tmp.isql(switches=['-q', '-n'], input_file = tmp_sql, combine_output=True)
# If following assert fails then act_tmp.db.db_path was unexpectedly removed from disk:
> assert act_tmp.clean_stdout == act_tmp.clean_expected_stdout
E assert
E MON$CRYPT_STATE 3
E DROP DATABASE;
E - Statement failed, SQLSTATE = 42000
E + Statement failed, SQLSTATE = 40001
E - unsuccessful metadata update
E + lock time-out on wait transaction
E -object is in use
E set echo off;
E DB_NAME /var/tmp/qa_2024/test_11480/tmp_gh_7200.tmp.fdb
tests/bugs/gh_7200_test.py:214: AssertionError
|