From 4f6ba72bc813c5afa296546c8fbba830e332351a Mon Sep 17 00:00:00 2001 From: pavel-zotov Date: Sat, 18 Jan 2025 17:19:36 +0300 Subject: [PATCH] Added/Updated tests\bugs\core_3323_test.py: Resultset of cursor that executes using instance of selectable PreparedStatement must be stored in some variable in order to have ability close it EXPLICITLY, before PS will be freed. Otherwise access violation can raises when Python runs garbage collection. --- tests/bugs/core_3323_test.py | 59 ++++++++++++++++++++++++++---------- 1 file changed, 43 insertions(+), 16 deletions(-) diff --git a/tests/bugs/core_3323_test.py b/tests/bugs/core_3323_test.py index 88d8f6ce..e5ce2289 100644 --- a/tests/bugs/core_3323_test.py +++ b/tests/bugs/core_3323_test.py @@ -22,7 +22,6 @@ DESCRIPTION: * every worker log must contain text 'SQLSTATE = 08003'; * no alive ISQL processes remain after issuing 'delete from mon$..' statements. JIRA: CORE-3323 -FBTEST: bugs.core_3323 NOTES: [17.11.2021] pcisar This test is too complicated and fragile (can screw the test environment) @@ -35,6 +34,13 @@ NOTES: or some trouble occurs with deleting from mon$attachments. Checked on 3.0.8.33535 (SS/CS), 4.0.1.2692 (SS/CS), 5.0.0.730 (SS/CS) - both Linux and Windows. + + [18.01.2025] pzotov + Resultset of cursor that executes using instance of selectable PreparedStatement must be stored + in some variable in order to have ability close it EXPLICITLY (before PS will be freed). + Otherwise access violation raises during Python GC and pytest hangs at final point (does not return control to OS). + This occurs at least for: Python 3.11.2 / pytest: 7.4.4 / firebird.driver: 1.10.6 / Firebird.Qa: 0.19.3 + The reason of that was explained by Vlad, 26.10.24 17:42 ("oddities when use instances of selective statements"). """ import time import datetime as py_dt @@ -46,6 +52,7 @@ from pathlib import Path import pytest from firebird.qa import * +from firebird.driver import DatabaseError ########################### ### S E T T I N G S ### @@ -65,7 +72,7 @@ MAX_WAIT_FOR_ISQL_START_MS = 3000 # because we kill its attachment (see 'p_isql.wait(...)'), seconds. # See also: https://docs.python.org/3/library/subprocess.html#subprocess.Popen.wait # -MAX_WAIT_FOR_ISQL_FINISH_S = 5 +MAX_WAIT_FOR_ISQL_FINISH_S = 10 init_ddl = f""" recreate table test(id int primary key using descending index test_id_desc); @@ -102,15 +109,16 @@ def test_1(act: Action, tmp_isql_cmds: List[Path], tmp_isql_logs: List[Path], ca where s.mon$attachment_id <> current_connection and s.mon$sql_text containing cast(? as varchar(20)) """ with con.cursor() as cur: - ps = cur.prepare(sql_check_appearance) - worker_att_list = [] - worker_log_list = [] - worker_pid_list = [] - - for worker_i in range(0, CONCURRENT_ATT_CNT): - worker_log_list.append( open(tmp_isql_logs[worker_i], 'w') ) - + ps, rs = None, None try: + ps = cur.prepare(sql_check_appearance) + worker_att_list = [] + worker_log_list = [] + worker_pid_list = [] + + for worker_i in range(0, CONCURRENT_ATT_CNT): + worker_log_list.append( open(tmp_isql_logs[worker_i], 'w') ) + for worker_i in range(0, CONCURRENT_ATT_CNT): if worker_i < CONCURRENT_ATT_CNT-1: @@ -147,7 +155,16 @@ def test_1(act: Action, tmp_isql_cmds: List[Path], tmp_isql_logs: List[Path], ca print(f'TIMEOUT EXPIRATION: waiting for ISQL process on iter {worker_i} took {dd} ms which exceeds limit = {MAX_WAIT_FOR_ISQL_START_MS} ms.') break - worker_att = cur.execute(ps, (f'TAG_{worker_i}',)).fetchone() + # ::: NB ::: 'ps' returns data, i.e. this is SELECTABLE expression. + # We have to store result of cur.execute() 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.execute(ps, (f'TAG_{worker_i}',)) + for r in rs: + worker_att = r + con.commit() if worker_att: @@ -159,23 +176,32 @@ def test_1(act: Action, tmp_isql_cmds: List[Path], tmp_isql_logs: List[Path], ca # result: all ISQLs are launched and their attachments are visible in mon$attachments (and can be traversed via worker_att_list) - ps = cur.prepare('delete from mon$attachments a where a.mon$attachment_id = ?') + kill_sttm = cur.prepare('delete from mon$attachments a where a.mon$attachment_id = ?') ################################################################### ### k i l l a t t a c h m e n t s o n e - b y - o n e ### ################################################################### for worker_id in reversed(worker_att_list): - cur.execute(ps, (worker_id,)) + cur.execute(kill_sttm, (worker_id,)) + + except DatabaseError as e: + print( e.__str__() ) + print(e.gds_codes) finally: - + if rs: + rs.close() # <<< EXPLICITLY CLOSING CURSOR RESULTS + if ps: + ps.free() + for i,p_isql in enumerate(worker_pid_list): p_isql.wait(MAX_WAIT_FOR_ISQL_FINISH_S) print(f'returncode for ISQL worker #{i}:',p.poll()) - for f in worker_log_list: f.close() + + # All worker logs must contain 'SQLSTATE = 08003' pattern (i.e. 'connection shutdown'): p_shutdown = re.compile('SQLSTATE\\s+=\\s+08003', re.IGNORECASE) for g in worker_log_list: @@ -185,8 +211,9 @@ def test_1(act: Action, tmp_isql_cmds: List[Path], tmp_isql_logs: List[Path], ca pass else: print('Pattern ',p_shutdown,' NOT FOUND in the log ',g.name,':') + print('=== beg of log ===') print(txt) - print('='*50) + print('=== end of log ===') con.commit() # NO any ISQL worker must be alive now: