Jump to: output_first_mismatch    outcomes_full_history    elapsed_time_chart
Show cross-report outcomes.

Annotation type Annotation details
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
Full history of outcomes and elapsed time, ms:
NN SNAP_INFO CS_outcome SS_outcome CS_run_time SS_run_time CS_run_beg CS_run_end SS_run_beg SS_run_end
1 4.0.6.3189 2025.02.25 1a1a5 P P 1015 1016 2025.06.29 15:51:59.045 2025.06.29 15:52:00.060 2025.06.29 14:38:01.600 2025.06.29 14:38:02.616
2 4.0.6.3184 2025.02.24 9388c P P 3059 2807 2025.02.25 13:46:50.631 2025.02.25 13:46:53.690 2025.02.25 12:27:54.828 2025.02.25 12:27:57.635
3 4.0.6.3183 2025.02.16 cf6ca P P 3029 2824 2025.02.17 07:41:00.633 2025.02.17 07:41:03.662 2025.02.17 06:21:29.470 2025.02.17 06:21:32.294
4 4.0.6.3169 2024.12.13 42cc1 P P 2996 2874 2025.02.16 04:38:13.555 2025.02.16 04:38:16.551 2025.02.16 03:20:49.830 2025.02.16 03:20:52.704
5 4.0.6.3169 2024.12.08 50eb6 P P 2856 2697 2024.12.12 18:55:36.167 2024.12.12 18:55:39.023 2024.12.12 17:53:41.657 2024.12.12 17:53:44.354
6 4.0.6.3168 2024.11.28 48149 P P 2776 2636 2024.12.06 03:16:35.492 2024.12.06 03:16:38.268 2024.12.06 02:16:18.354 2024.12.06 02:16:20.990
7 4.0.6.3163 2024.10.16 2bb10 P P 2824 2674 2024.11.27 13:41:10.588 2024.11.27 13:41:13.412 2024.11.27 10:39:56.647 2024.11.27 10:39:59.321
8 4.0.6.3163 2024.10.15 f387e P P 2836 2626 2024.10.16 04:46:33.037 2024.10.16 04:46:35.873 2024.10.16 03:49:16.487 2024.10.16 03:49:19.113
9 4.0.6.3147 2024.08.31 4655b P P 2877 2749 2024.09.30 12:02:33.772 2024.09.30 12:02:36.649 2024.09.30 10:58:34.360 2024.09.30 10:58:37.109
10 4.0.6.3140 2024.08.16 1dd8b P P 4510 3554 2024.08.31 18:33:02.149 2024.08.31 18:33:06.659 2024.08.31 16:38:01.142 2024.08.31 16:38:04.696
11 4.0.6.3140 2024.08.09 34747 P P 3067 2820 2024.08.16 11:07:21.218 2024.08.16 11:07:24.285 2024.08.16 09:57:41.369 2024.08.16 09:57:44.189
12 4.0.5.3110 2024.07.30 c6527 P P 3327 2822 2024.08.09 10:58:11.402 2024.08.09 10:58:14.729 2024.08.09 09:48:54.066 2024.08.09 09:48:56.888
13 4.0.5.3109 2024.06.11 6addf P F 2761 2620 2024.07.30 09:17:08.731 2024.07.30 09:17:11.492 2024.07.30 08:16:17.749 2024.07.30 08:16:20.369
14 4.0.5.3097 2024.05.09 27fa6 P P 2926 2748 2024.05.14 10:01:35.401 2024.05.14 10:01:38.327 2024.05.14 08:59:32.546 2024.05.14 08:59:35.294
15 4.0.5.3091 2024.04.29 bd0aa P P 2689 2552 2024.05.08 21:03:19.686 2024.05.08 21:03:22.375 2024.05.08 20:10:14.478 2024.05.08 20:10:17.030
16 4.0.5.3089 2024.04.25 4b9c7 P P 2729 2559 2024.04.27 15:47:51.304 2024.04.27 15:47:54.033 2024.04.27 14:54:03.393 2024.04.27 14:54:05.952

Elapsed time, ms. Chart for last 16 runs:

Last commits information (all timestamps in UTC):