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_11464/tmp_gh_7200.tmp.fdb
LOG DETAILS:
2024-07-30 11:29:22.035
2024-07-30 11:29:22.040 act = <firebird.qa.plugin.Action object at [hex]>
2024-07-30 11:29:22.052 act_tmp = <firebird.qa.plugin.Action object at [hex]>
2024-07-30 11:29:22.062 tmp_sql = PosixPath('/var/tmp/qa_2024/test_11464/tmp_gh_7200.tmp.sql')
2024-07-30 11:29:22.071 tmp_log = PosixPath('/var/tmp/qa_2024/test_11464/tmp_gh_7200.tmp.log')
2024-07-30 11:29:22.079 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-07-30 11:29:22.085
2024-07-30 11:29:22.091 @pytest.mark.encryption
2024-07-30 11:29:22.097 @pytest.mark.version('>=4.0.2')
2024-07-30 11:29:22.103 def test_1(act: Action, act_tmp: Action, tmp_sql: Path, tmp_log: Path, capsys):
2024-07-30 11:29:22.109
2024-07-30 11:29:22.115 init_sql = f"""
2024-07-30 11:29:22.120 recreate table test(s varchar({FLD_LEN}));
2024-07-30 11:29:22.125 commit;
2024-07-30 11:29:22.131 set term ^;
2024-07-30 11:29:22.137 execute block as
2024-07-30 11:29:22.142 declare n int = {N_ROWS};
2024-07-30 11:29:22.148 begin
2024-07-30 11:29:22.153 while (n>0) do
2024-07-30 11:29:22.163 begin
2024-07-30 11:29:22.173 insert into test(s) values(lpad('', {FLD_LEN}, uuid_to_char(gen_uuid())));
2024-07-30 11:29:22.181 n = n - 1;
2024-07-30 11:29:22.187 end
2024-07-30 11:29:22.199 end
2024-07-30 11:29:22.210 ^
2024-07-30 11:29:22.218 -- for debug, trace must be started with log_proc = true:
2024-07-30 11:29:22.226 create procedure sp_debug (a_point varchar(50)) as
2024-07-30 11:29:22.233 begin
2024-07-30 11:29:22.241 -- nop --
2024-07-30 11:29:22.247 end
2024-07-30 11:29:22.259 ^
2024-07-30 11:29:22.270 set term ;^
2024-07-30 11:29:22.277 commit;
2024-07-30 11:29:22.284 create index test_s on test(s);
2024-07-30 11:29:22.290 """
2024-07-30 11:29:22.296 act_tmp.isql(switches=['-q'], input = init_sql, combine_output = True)
2024-07-30 11:29:22.306 assert act_tmp.clean_stdout == ''
2024-07-30 11:29:22.315 act_tmp.reset()
2024-07-30 11:29:22.323
2024-07-30 11:29:22.330 #############################################
2024-07-30 11:29:22.336 ### c h a n g e F W t o O N ###
2024-07-30 11:29:22.342 #############################################
2024-07-30 11:29:22.348 act_tmp.db.set_sync_write()
2024-07-30 11:29:22.353
2024-07-30 11:29:22.359
2024-07-30 11:29:22.365 # QA_GLOBALS -- dict, is defined in qa/plugin.py, obtain settings
2024-07-30 11:29:22.371 # from act.files_dir/'test_config.ini':
2024-07-30 11:29:22.376 enc_settings = QA_GLOBALS['encryption']
2024-07-30 11:29:22.382
2024-07-30 11:29:22.388 encryption_plugin = enc_settings['encryption_plugin'] # fbSampleDbCrypt
2024-07-30 11:29:22.394 encryption_holder = enc_settings['encryption_holder'] # fbSampleKeyHolder
2024-07-30 11:29:22.400 encryption_key = enc_settings['encryption_key'] # Red
2024-07-30 11:29:22.405
2024-07-30 11:29:22.412 sttm = f'alter database encrypt with "{encryption_plugin}" key "{encryption_key}";'
2024-07-30 11:29:22.417 tmp_sql.write_bytes(sttm.encode('utf-8'))
2024-07-30 11:29:22.423
2024-07-30 11:29:22.428 with tmp_log.open('w') as f_log:
2024-07-30 11:29:22.434
2024-07-30 11:29:22.439 p = subprocess.Popen( [ act_tmp.vars['isql'],
2024-07-30 11:29:22.445 '-q',
2024-07-30 11:29:22.451 '-user', act_tmp.db.user,
2024-07-30 11:29:22.457 '-password', act_tmp.db.password,
2024-07-30 11:29:22.466 act_tmp.db.dsn,
2024-07-30 11:29:22.478 '-i', tmp_sql
2024-07-30 11:29:22.486 ],
2024-07-30 11:29:22.498 stdout = f_log, stderr = subprocess.STDOUT
2024-07-30 11:29:22.509 )
2024-07-30 11:29:22.517
2024-07-30 11:29:22.525 encryption_started = False
2024-07-30 11:29:22.531 with act_tmp.db.connect() as con_watcher:
2024-07-30 11:29:22.537
2024-07-30 11:29:22.543 custom_tpb = tpb(isolation = Isolation.SNAPSHOT, lock_timeout = -1)
2024-07-30 11:29:22.549 tx_watcher = con_watcher.transaction_manager(custom_tpb)
2024-07-30 11:29:22.555 cur_watcher = tx_watcher.cursor()
2024-07-30 11:29:22.560
2024-07-30 11:29:22.566 # 0 = non-encrypted; 1 = encrypted; 2 = is DEcrypting; 3 - is Encrypting
2024-07-30 11:29:22.572 ps = cur_watcher.prepare('select mon$crypt_state from mon$database')
2024-07-30 11:29:22.578
2024-07-30 11:29:22.584 i = 0
2024-07-30 11:29:22.590 da = dt.now()
2024-07-30 11:29:22.596 while True:
2024-07-30 11:29:22.602 cur_watcher.execute(ps)
2024-07-30 11:29:22.608 for r in cur_watcher:
2024-07-30 11:29:22.614 db_crypt_state = r[0]
2024-07-30 11:29:22.620
2024-07-30 11:29:22.626 tx_watcher.commit()
2024-07-30 11:29:22.632 db = dt.now()
2024-07-30 11:29:22.640 diff_ms = (db-da).seconds*1000 + (db-da).microseconds//1000
2024-07-30 11:29:22.653 if db_crypt_state == IS_ENCRYPTING_STATE:
2024-07-30 11:29:22.664 encryption_started = True
2024-07-30 11:29:22.673 cur_watcher.call_procedure('sp_debug', ('encryption_started',))
2024-07-30 11:29:22.681 break
2024-07-30 11:29:22.688 elif diff_ms > MAX_WAIT_FOR_ENCRYPTION_START_MS:
2024-07-30 11:29:22.694 break
2024-07-30 11:29:22.700
2024-07-30 11:29:22.706 time.sleep(0.1)
2024-07-30 11:29:22.711
2024-07-30 11:29:22.717 ps.free()
2024-07-30 11:29:22.722
2024-07-30 11:29:22.731 assert encryption_started, f'Could not find start of encryption process for {MAX_WAIT_FOR_ENCRYPTION_START_MS} ms.'
2024-07-30 11:29:22.740
2024-07-30 11:29:22.748 #-----------------------------------------------------------------
2024-07-30 11:29:22.754
2024-07-30 11:29:22.760 drop_db_when_running_encryption_sql = f"""
2024-07-30 11:29:22.765 set list on;
2024-07-30 11:29:22.771 select mon$crypt_state from mon$database;
2024-07-30 11:29:22.776 commit;
2024-07-30 11:29:22.782 set echo on;
2024-07-30 11:29:22.788 DROP DATABASE;
2024-07-30 11:29:22.793 set echo off;
2024-07-30 11:29:22.800 select lower(rdb$get_context('SYSTEM', 'DB_NAME')) as db_name from rdb$database;
2024-07-30 11:29:22.805 """
2024-07-30 11:29:22.811 tmp_sql.write_text(drop_db_when_running_encryption_sql)
2024-07-30 11:29:22.816
2024-07-30 11:29:22.825 drop_db_expected_stdout = f"""
2024-07-30 11:29:22.834 MON$CRYPT_STATE {IS_ENCRYPTING_STATE}
2024-07-30 11:29:22.842 DROP DATABASE;
2024-07-30 11:29:22.849 Statement failed, SQLSTATE = 42000
2024-07-30 11:29:22.855 unsuccessful metadata update
2024-07-30 11:29:22.861 -object is in use
2024-07-30 11:29:22.866 set echo off;
2024-07-30 11:29:22.872 DB_NAME {str(act_tmp.db.db_path).lower()}
2024-07-30 11:29:22.877 """
2024-07-30 11:29:22.883
2024-07-30 11:29:22.889 act_tmp.expected_stdout = drop_db_expected_stdout
2024-07-30 11:29:22.895
2024-07-30 11:29:22.901 # Get current state of encryption (again, just for additional check)
2024-07-30 11:29:22.907 # and attempt to DROP database:
2024-07-30 11:29:22.913 ###############################
2024-07-30 11:29:22.919 act_tmp.isql(switches=['-q', '-n'], input_file = tmp_sql, combine_output=True)
2024-07-30 11:29:22.925
2024-07-30 11:29:22.931 # If following assert fails then act_tmp.db.db_path was unexpectedly removed from disk:
2024-07-30 11:29:22.938 > assert act_tmp.clean_stdout == act_tmp.clean_expected_stdout
2024-07-30 11:29:22.944 E assert
2024-07-30 11:29:22.949 E MON$CRYPT_STATE 3
2024-07-30 11:29:22.955 E DROP DATABASE;
2024-07-30 11:29:22.961 E - Statement failed, SQLSTATE = 42000
2024-07-30 11:29:22.973 E + Statement failed, SQLSTATE = 40001
2024-07-30 11:29:22.985 E - unsuccessful metadata update
2024-07-30 11:29:22.990 E + lock time-out on wait transaction
2024-07-30 11:29:22.996 E -object is in use
2024-07-30 11:29:23.002 E set echo off;
2024-07-30 11:29:23.008 E DB_NAME /var/tmp/qa_2024/test_11464/tmp_gh_7200.tmp.fdb
2024-07-30 11:29:23.014
2024-07-30 11:29:23.024 tests/bugs/gh_7200_test.py:193: AssertionError
2024-07-30 11:29:23.033 ---------------------------- Captured stdout setup -----------------------------
2024-07-30 11:29:23.041 Cached db: db-13.0-16384-None-NONE.fdb [page_size=16384, sql_dialect=None, charset='NONE'
2024-07-30 11:29:23.048 Cached db: db-13.0-None-None-NONE.fdb [page_size=None, sql_dialect=None, charset='NONE'
|
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_11464/tmp_gh_7200.tmp.sql')
tmp_log = PosixPath('/var/tmp/qa_2024/test_11464/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:
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:
cur_watcher.execute(ps)
for r in cur_watcher:
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)
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_11464/tmp_gh_7200.tmp.fdb
tests/bugs/gh_7200_test.py:193: AssertionError
|