firebird-qa/tests/bugs/core_6048_test.py

#coding:utf-8

"""
ID:          issue-6298
ISSUE:       6298
TITLE:       Provide ability to see current state of DB encryption
DESCRIPTION:
    Test adds lot of data to database, issues 'alter database encrypt ...' and starts loop with query:
    'select mon$crypt_page, mon$crypt_state from mon$database', with repeating it every 1 second.
    Loop continues until we find that mon$crypt_state become 1, or if <MAX_ENCRYPT_DECRYPT_MS> ms expired.
    On every iteration of this loop we accumulate pairs (mon$crypt_page, mon$crypt_state) in the list,
    and when encryption completes we check that:
        * at least two measures could be done (i.e. there was no hang of query to mon$ table during encryption);
        * last query to mon$database returned mon$crypt_page =0 and mon$crypt_state = 1 (i.e. encryption was actually finished).
JIRA:        CORE-6048
FBTEST:      bugs.core_6048
NOTES:
    [13.06.2022] pzotov
    Checked on 5.0.0.509 - both on Linux and Windows.
    
    ::: NB-1 :::
    Currently test must check only FB 5.0! Encryption in FB 3.x and 4.x *block* obtaining data from monitoring tables.
    See also: https://github.com/FirebirdSQL/firebird/issues/6947

    ::: NB-2 :::
    Number of records that will be added into table must be sufficient big to force encryption thread work at least 3 seconds,
    but - at the same time - it must not be too large because we have time limit <MAX_ENCRYPT_DECRYPT_MS> which must not be exeeded.
    Careful tuning required on each tesing box for this test.
"""

import os
import time
import datetime as py_dt
from datetime import timedelta

import pytest
from firebird.qa import *
from firebird.driver import DatabaseError, DbWriteMode

########################### ACHTUNG ###############
# this must be carefully tuned on every new host: #
###################################################
N_ROWS =15000 if os.name == 'nt' else 5000

F_LEN = 16383
init_script = f"""
    set bail on;
    create table tlog(id bigint generated by default as identity constraint pk_tlog primary key, crypt_page int, crypt_state smallint);
    create table test(s varchar({F_LEN}));
    commit;
    set term ^;
    execute block as
        declare n bigint = {N_ROWS};
    begin
        while (n>0) do
        begin
            insert into test(s) values( lpad('',{F_LEN}, uuid_to_char(gen_uuid())) );
            n = n - 1;
        end
    end
    ^
    commit
    ^
"""

db = db_factory(init = init_script, utf8filename = False, charset='none')
act = python_act('db', substitutions=[('[ \t]+', ' ')])

expected_stdout = """
    Number of distinct values of mon$crypt_page: EXPECTED
    Last measured values of mon$crypt_page and mon$crypt_state: EXPECTED
"""

@pytest.mark.encryption
@pytest.mark.version('>=5.0')
def test_1(act: Action, capsys):

    # QA_GLOBALS -- dict, is defined in qa/plugin.py, obtain settings
    # from act.files_dir/'test_config.ini':
    enc_settings = QA_GLOBALS['encryption']

    MAX_ENCRYPT_DECRYPT_MS = int(enc_settings['max_encrypt_decrypt_ms']) # 5000 // was: 60'000
    ENCRYPTION_PLUGIN = enc_settings['encryption_plugin'] # fbSampleDbCrypt
    ENCRYPTION_KEY = enc_settings['encryption_key'] # Red
   
    with act.connect_server() as srv:
        srv.database.set_write_mode(database=act.db.db_path, mode=DbWriteMode.SYNC)

    encryption_finished = False
    encryption_started = False
    with act.db.connect() as con, act.db.connect() as con2:

        t1=py_dt.datetime.now()
        d1 = t1-t1
        sttm = f'alter database encrypt with "{ENCRYPTION_PLUGIN}" key "{ENCRYPTION_KEY}"'
        try:
            con.execute_immediate(sttm)
            con.commit()
            encryption_started = True
        except DatabaseError as e:
            # -ALTER DATABASE failed
            # -Crypt plugin fbSampleDbCrypt failed to load
            #  ==> no sense to do anything else, encryption_started remains False.
            print( e.__str__() )

        cur2 = con2.cursor()
        ps = cur2.prepare('select mon$crypt_page, mon$crypt_state from mon$database')
        crypt_chronolody = []
        while encryption_started:
            t2=py_dt.datetime.now()
            d1=t2-t1
            if d1.seconds*1000 + d1.microseconds//1000 > MAX_ENCRYPT_DECRYPT_MS:
                print(f'TIMEOUT EXPIRATION: encryption took {d1.seconds*1000 + d1.microseconds//1000} ms which exceeds limit = {MAX_ENCRYPT_DECRYPT_MS} ms.')
                break

            cur2.execute(ps)
            crypt_page, crypt_state = cur2.fetchone()
            crypt_chronolody.append( (crypt_page, crypt_state) )
            con2.commit()

            # 0 = non crypted;
            # 1 = has been encrypted;
            # 2 = is DEcrypting;
            # 3 = is Encrypting;
            if crypt_state == 1:
                encryption_finished = True
                break
            else:
                time.sleep(1)

        if encryption_started: # encryption_finished:
            crypt_chrono_pset = set([ p[0] for p in crypt_chronolody if p[1] == 3 ])
            crypt_chrono_last = crypt_chronolody[-1]

            if len( crypt_chrono_pset ) > 1:
                logged_unique_crypt_pages_msg = 'EXPECTED'
            else:
                logged_unique_crypt_pages_msg = 'UNEXPECTED: len = %d; list: %s' % ( len(crypt_chrono_pset),  ','.join( (str(x) for x in sorted(crypt_chrono_pset)) ) )

            print('Number of distinct values of mon$crypt_page: %s' % logged_unique_crypt_pages_msg)

            if crypt_chrono_last == (0,1):
                logged_last_crypt_page_state_msg = 'EXPECTED'
            else:
                logged_last_crypt_page_state_msg = 'UNEXPECTED: %s' % ','.join( (str(x) for x in crypt_chrono_last) )

            print('Last measured values of mon$crypt_page and mon$crypt_state: %s' % logged_last_crypt_page_state_msg)

        act.expected_stdout = expected_stdout
        act.stdout = capsys.readouterr().out
        assert act.clean_stdout == act.clean_expected_stdout
        act.reset()