Added/Updated tests\bugs\gh_7917_test.py: Checked on 4.0.5.3053, 5.0.1.1327, 6.0.0.230 (intermediate snapshots; all in CS/SS).

Author: pavel-zotov

tests/bugs/gh_7917_test.py

@@ -38,12 +38,13 @@
     Great thanks to Alex for suggestions (discussion started 13.12.2023 13:18).
 
     Confirmed bug on 6.0.0.173.
-    Checked on 6.0.0.175, 5.0.0.1305, 4.0.5.3049 - but currenlyt only SuperServer works fine.
-    Classic has the same problem. Sent report to Alex, 28.12.2023 13:10.
-
-    On 3.0.12.33726 error raises:
-        unsuccessful metadata update / -ALTER DATABASE failed / -Missing correct crypt key / -Plugin fbSampleDbCrypt: / -Crypt key not set
-    This problem not [yet] investogated.
+    
+    [30.01.2024] pzotov
+    Checked on 4.0.5.3053, 5.0.1.1327, 6.0.0.230 (intermediate snapshots; all in CS/SS).
+    Commits:
+        6.x: https://github.com/FirebirdSQL/firebird/commit/8295aeb26ccee4f9a644c6928e598abbe06c31c0
+        5.x: https://github.com/FirebirdSQL/firebird/commit/6f393ba762f390f69f895acc091583a3e486f4d0
+        4.x: https://github.com/FirebirdSQL/firebird/commit/4c21cae77886461e68c2cab68ec063b416492e61
 """
 import os
 import time
@@ -78,19 +79,23 @@
 SWP_INTERVAL_TO_CHECK = 100
 TX_NUMBER_BEFORE_HANG = SWP_INTERVAL_TO_CHECK + 10
 
+MAX_WAIT_FOR_ISQL_TERMINATE=11
+
 db = db_factory(filename = '#' + REQUIRED_ALIAS)
 
-act = python_act('db', substitutions = [('TCPv(4|6)$', 'TCP')])
+act = python_act('db', substitutions = [('^((?!(ISQL|Attributes)).)*$', ''), ('[ \t]+', ' '), ('TCPv(4|6)$', 'TCP')])
+#act = python_act('db')
 
 tmp_sql_file = temp_file('tmp_7917.sql')
-tmp_log_file = temp_file('tmp_7917.log')
+tmp_log_file = temp_file('tmp_7917_isql.log')
+tmp_gstat_log = temp_file('tmp_7917_gstat.log')
 
 #-----------------------------------------------------------------------
 
 def run_encr_decr(act: Action, mode, max_wait_encr_thread_finish, capsys):
     if mode == 'encrypt':
         # See letter from Alex, 15.12.2023 16:16 demo-plugin can not transfer named key over network.
-        # Because of that, we have to use following command WITHOUT adding 'key "{ENCRYPTION_KEY}"':
+        # Because of that, we have to use 'ALTER DATABASE ENCRYPT WITH <plugin>'  _WITHOUT_ adding 'key "{ENCRYPTION_KEY}"'.
         # ::: NB ::: One need to be sure that $FB_HOME/plugins.conf contains following lines:
         # Plugin = KH2 {
         #     Module = $(dir_plugins)/fbSampleKeyHolder
@@ -107,66 +112,61 @@ def run_encr_decr(act: Action, mode, max_wait_encr_thread_finish, capsys):
         # -Plugin fbSampleDbCrypt:
         # -Crypt key not set
         #
-        alter_db_sttm = f'alter database encrypt with "{ENCRYPTION_PLUGIN}"'
+        alter_db_sttm = f'alter database encrypt with "{ENCRYPTION_PLUGIN}"' # <<< ::: NB ::: DO NOT add '... key "{ENCRYPTION_KEY}"' here!
         wait_for_state = 'Database encrypted'
     elif mode == 'decrypt':
         alter_db_sttm = 'alter database decrypt'
         wait_for_state = 'Database not encrypted'
 
 
-    e_thread_started = False
     e_thread_finished = False
+
+    # 0 = non crypted;
+    # 1 = has been encrypted;
+    # 2 = is DEcrypting;
+    # 3 = is Encrypting;
+    #
+    REQUIRED_CRYPT_STATE = 1 if mode == 'encrypt' else 0
+    current_crypt_state = -1
+    d1 = py_dt.timedelta(0)
     with act.db.connect() as con:
+        cur = con.cursor()
+        ps = cur.prepare('select mon$crypt_state from mon$database')
 
         t1=py_dt.datetime.now()
-        d1 = t1-t1
         try:
+            d1 = t1-t1
             con.execute_immediate(alter_db_sttm)
             con.commit()
-            e_thread_started = True
-        except DatabaseError as e:
-            print( e.__str__() )
-
-        while e_thread_started:
-            t2=py_dt.datetime.now()
-            d1=t2-t1
-            if d1.seconds*1000 + d1.microseconds//1000 > max_wait_encr_thread_finish:
-                print(f'TIMEOUT EXPIRATION. Mode="{mode}" took {d1.seconds*1000 + d1.microseconds//1000} ms which exceeds limit = {max_wait_encr_thread_finish} ms.')
-                break
-
-            # Possible output:
-            #     Database [not] encrypted
-            #     Database encrypted, crypt thread not complete
-            act.isql(switches=['-q'], input = 'show database;', combine_output = True)
-            if wait_for_state in act.stdout:
-                if 'not complete' in act.stdout:
-                    pass
-                else:
+            while True:
+                t2=py_dt.datetime.now()
+                d1=t2-t1
+                if d1.seconds*1000 + d1.microseconds//1000 > max_wait_encr_thread_finish:
+                    break
+    
+                ######################################################
+                ###   C H E C K    M O N $ C R Y P T _ S T A T E   ###
+                ######################################################
+                cur.execute(ps)
+                current_crypt_state = cur.fetchone()[0]
+                con.commit()
+                if current_crypt_state == REQUIRED_CRYPT_STATE:
                     e_thread_finished = True
                     break
-            act.reset()
-
-        act.expected_stdout = ''
-        act.stdout = capsys.readouterr().out
-        assert act.clean_stdout == act.clean_expected_stdout
-        act.reset()
+                else:
+                    time.sleep(0.5)
+        except DatabaseError as e:
+            print( e.__str__() )
 
-    assert e_thread_finished
+    assert e_thread_finished, f'TIMEOUT EXPIRATION. Mode="{mode}" took {d1.seconds*1000 + d1.microseconds//1000} ms which exceeds limit = {max_wait_encr_thread_finish} ms; current_crypt_state={current_crypt_state}'
 
 
 #-----------------------------------------------------------------------
 
-@pytest.mark.skip("FIXME: hangs on IBSurgeon test server.")
 @pytest.mark.encryption
 @pytest.mark.version('>=4.0.5')
 @pytest.mark.platform('Windows')
-def test_1(act: Action, tmp_sql_file: Path, tmp_log_file: Path, capsys):
-
-    with act.db.connect() as con:
-        if act.vars['server-arch'] == 'SuperServer':
-            pass
-        else:
-            pytest.skip("Currently fixed only for SuperServer. Temporary SKIPPED.")
+def test_1(act: Action, tmp_sql_file: Path, tmp_log_file: Path, tmp_gstat_log: Path, capsys):
 
     # Scan line-by-line through databases.conf, find line starting with REQUIRED_ALIAS and extract name of file that
     # must be created in the $(dir_sampleDb)/qa/ folder. This name will be used further as target database (tmp_fdb).
@@ -187,8 +187,9 @@ def test_1(act: Action, tmp_sql_file: Path, tmp_log_file: Path, capsys):
     #
     assert fname_in_dbconf
 
-    #----------------------------------------------------------------
-
+    ############################################
+    ###   E N C R Y P T    D A T A B A S E   ###
+    ############################################
     run_encr_decr(act, 'encrypt', MAX_WAITING_ENCR_FINISH, capsys)
 
     test_script = f"""
@@ -207,20 +208,14 @@ def test_1(act: Action, tmp_sql_file: Path, tmp_log_file: Path, capsys):
             declare v_swp_interval int;
             declare v_protocol type of column att_log.att_prot;
         begin
-            select a.mon$remote_protocol, d.mon$sweep_interval
-            from mon$attachments a
-            cross join mon$database d
-            where a.mon$attachment_id = current_connection
-            into v_protocol, v_swp_interval;
             insert into att_log(
                  att_prot
                 ,evt_name
-                ,swp_interval
             ) values (
-                 :v_protocol
+                 rdb$get_context('SYSTEM', 'NETWORK_PROTOCOL')
                 ,:a_evt_name
-                ,:v_swp_interval
             );
+
         end
         ^
         create or alter trigger trg_detach on disconnect as
@@ -282,36 +277,60 @@ def test_1(act: Action, tmp_sql_file: Path, tmp_log_file: Path, capsys):
     #
     act.gfix(switches=['-h', f'{SWP_INTERVAL_TO_CHECK}', act.db.dsn], combine_output = True, io_enc = locale.getpreferredencoding())
 
-    # Launch ISQL which will hang because update conflict.
-    # This ISQl will be 'self-terminated' further because we will change DB state to full shutdown:
+    # gstat -h tmp_gh_7917_alias must show at this point:
+    # Attributes              encrypted, plugin fbSampleDbCrypt
+    # ...
+    # Sweep interval:         100
     #
-    p_handed_isql = subprocess.Popen([act.vars['isql'], '-nod', '-i', str(tmp_sql_file),
-                                   '-user', act.db.user,
-                                   '-password', act.db.password, act.db.dsn],
-                                  stderr = subprocess.STDOUT)
-    time.sleep(2)
-
-    try:
-        act.gfix(switches=['-shut', 'full', '-force', '0', act.db.dsn], combine_output = True, io_enc = locale.getpreferredencoding())
-    finally:
-        p_handed_isql.terminate()
-        p_handed_isql.wait()
+    with open(tmp_log_file, 'w') as f:
+        # Launch ISQL which will hang because update conflict.
+        # This ISQl will be 'self-terminated' further because we will change DB state to full shutdown:
+        #
+        p_handed_isql = subprocess.Popen([act.vars['isql'], '-nod', '-i', str(tmp_sql_file),
+                                       '-user', act.db.user,
+                                       '-password', act.db.password, act.db.dsn],
+                                      stdout = f,
+                                      stderr = subprocess.STDOUT)
+
+        # Let ISQL time to establish connection and fall in hanging state:
+        time.sleep(3)
+
+        try:
+            act.gfix(switches=['-shut', 'full', '-force', '0', act.db.dsn], combine_output = True, io_enc = locale.getpreferredencoding())
+        finally:
+            p_handed_isql.terminate()
+
+        p_handed_isql.wait(MAX_WAIT_FOR_ISQL_TERMINATE)
+        if p_handed_isql.poll() is None:
+            print(f'Hanged ISQL process WAS NOT terminated in {MAX_WAIT_FOR_ISQL_TERMINATE} second(s).!')
+        else:
+            print(f'Hanged ISQL process terminated with retcode = {p_handed_isql.poll()}')
 
+    # Result: log of hanged ISQL must contain now:
+    # Statement failed, SQLSTATE = 08003
+    # connection shutdown
+    # -Database is shutdown.    
+    
     act.gfix(switches=['-online', act.db.dsn], combine_output = True, io_enc = locale.getpreferredencoding())
     assert act.clean_stdout == ''
     act.reset()
 
+    # Must show: Attributes encrypted, plugin {ENCRYPTION_PLUGIN} - without 'shutdown'.
+    # This is needed only for debug:
+    with open(tmp_gstat_log, 'w') as f:
+        subprocess.run( [ act.vars['gstat'], '-h', act.db.db_path, '-user', act.db.user, '-pas', act.db.password ], stdout = f, stderr = subprocess.STDOUT )
+
     #----------------------------------------------------------------
 
+    TEST_QUERY = 'select att_prot,who_ami,evt_name from att_log order by trn_id'
     final_sql = f"""
-        set count on;
         set list on;
-        select att_prot,who_ami,evt_name,swp_interval from att_log
-        order by trn_id;
+        select mon$crypt_state from mon$database;
+        {TEST_QUERY};
+        quit;
     """
     tmp_sql_file.write_text(final_sql)
 
-
     with open(tmp_log_file, 'w') as f:
         # Explained by Alex, letter 13-dec-2023 13:18.
         # Following ISQL will create attach that provokes AUTO SWEEP (because Next - OST now greater than SWP_INTERVAL_TO_CHECK).
@@ -342,44 +361,38 @@ def test_1(act: Action, tmp_sql_file: Path, tmp_log_file: Path, capsys):
             print(e.__str__())
 
         p_chk_sql.terminate()
+        p_chk_sql.wait(MAX_WAIT_FOR_ISQL_TERMINATE)
 
         # Check if child process has terminated. Set and return returncode attribute. Otherwise, returns None.
         if p_chk_sql.poll() is None:
-            print('Final ISQL process WAS NOT terminated!')
+            print(f'### ERROR ### Final ISQL process WAS NOT terminated in {MAX_WAIT_FOR_ISQL_TERMINATE} second(s).!')
         else:
-            print(f'Final ISQL process terminated with retcode = {p_chk_sql.poll()}')
+            print(f'Final ISQL process terminated')
+            #print(f'Final ISQL process terminated with retcode = {p_chk_sql.poll()}')
 
+    ############################################
+    ###   D E C R Y P T    D A T A B A S E   ###
+    ############################################
+    run_encr_decr(act, 'decrypt', MAX_WAITING_ENCR_FINISH, capsys)
 
-    # do NOT put here this:
-    #run_encr_decr(act, 'decrypt', MAX_WAITING_ENCR_FINISH, capsys)
-    # - otherwise pytest will not return control
-    
     with open(tmp_log_file, 'r') as f:
         for line in f:
             if line.strip():
-                print('final ISQL log:',line)
+                print(line)
 
     act.expected_stdout = f"""
-        Final ISQL process terminated with retcode = 0
-        final ISQL log: ATT_PROT                        TCP
-        final ISQL log: WHO_AMI                         {act.db.user.upper()}
-        final ISQL log: EVT_NAME                        attach
-        final ISQL log: SWP_INTERVAL                    {SWP_INTERVAL_TO_CHECK}
-
-        final ISQL log: ATT_PROT                        TCP
-        final ISQL log: WHO_AMI                         {act.db.user.upper()}
-        final ISQL log: EVT_NAME                        detach
-        final ISQL log: SWP_INTERVAL                    {SWP_INTERVAL_TO_CHECK}
-
-        final ISQL log: Records affected: 2
+        Hanged ISQL process terminated with retcode = 1
+        Final ISQL process terminated
+
+        ATT_PROT                        TCP
+        WHO_AMI                         {act.db.user.upper()}
+        EVT_NAME                        attach
+
+        ATT_PROT                        TCP
+        WHO_AMI                         {act.db.user.upper()}
+        EVT_NAME                        detach
     """
 
     act.stdout = capsys.readouterr().out
     assert act.clean_stdout == act.clean_expected_stdout
     act.reset()
-
-    # NB! We have to decrypt database now. Otherwise teardown will fail with:
-    #   firebird.driver.types.DatabaseError: Missing database encryption key for your attachment
-    #   -Plugin fbSampleDbCrypt:
-    #   -Crypt key not set
-    run_encr_decr(act, 'decrypt', MAX_WAITING_ENCR_FINISH, capsys)