firebird/firebird-qa
6
0
Fork 0
mirror of https://github.com/FirebirdSQL/firebird-qa.git synced 2025-01-22 21:43:06 +01:00
Code Issues Activity

Added/Updated bugs\core_4337_test.py. Removed check of sweep log: sometime it can remain empty, for unknown reason (detected on 4.0.1 Classic). Added loop with check for several seconds for appearance of 2nd gfix attach - as it was initially implemented in fbt.

Browse Source
This commit is contained in:
zotov 2022-09-25 16:02:24 +03:00
parent 6ebb2e3824
commit 49c162c060
1 changed files with 64 additions and 23 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

81
tests/bugs/core_4337_test.py
View File

@ -68,7 +68,7 @@ substitutions = [
('FIREBIRD.LOG:.* ERROR DURING SWEEP OF .*TEST.FDB.*', 'FIREBIRD.LOG: + ERROR DURING SWEEP OF TEST.FDB') ('FIREBIRD.LOG:.* ERROR DURING SWEEP OF .*TEST.FDB.*', 'FIREBIRD.LOG: + ERROR DURING SWEEP OF TEST.FDB')
] ]
make_garbage = """ init_sql = """
set list on; set list on;
recreate table t( recreate table t(
s01 varchar(4000) s01 varchar(4000)
@ -115,7 +115,7 @@ make_garbage = """
# 16K page is neccessary ! Smaller size will cause failure with: # 16K page is neccessary ! Smaller size will cause failure with:
# key size exceeds implementation restriction for index "T_S01" # key size exceeds implementation restriction for index "T_S01"
# #
db = db_factory(page_size=16384, init = make_garbage) db = db_factory(page_size=16384, init = init_sql)
act = python_act('db', substitutions = substitutions) act = python_act('db', substitutions = substitutions)
@ -143,10 +143,14 @@ def test_1(act: Action, sweep_log: Path, capsys):
#--------------------------------------------------------------- #---------------------------------------------------------------
# How long can we wait for appearance of 'gfix' process in the mon$attachments, ms: # How long can we wait (milliseconds) for the FIRST appearance of 'gfix' process in mon$attachments:
# #
MAX_WAIT_FOR_SWEEP_START_MS = 3000 MAX_WAIT_FOR_SWEEP_START_MS = 3000
# How long we wait (milliseconds) for SECOND appearance of 'gfix' process in mon$attachments, after it was killed.
# NOTE. If it appears then we have a BUG
MAX_WAIT_FOR_GFIX_RESTART_MS = 3000
sweep_attach_id = None sweep_attach_id = None
sweep_reconnect = None sweep_reconnect = None
# Start trace # Start trace
@ -157,7 +161,14 @@ def test_1(act: Action, sweep_log: Path, capsys):
t1=py_dt.datetime.now() t1=py_dt.datetime.now()
with con.cursor() as cur: with con.cursor() as cur:
ps = cur.prepare(stm) ps = cur.prepare(stm)
p_sweep = subprocess.Popen( [act.vars['gfix'], '-sweep', '-user', act.db.user, '-password', act.db.password, act.db.dsn], stdout = f_sweep_log, stderr = subprocess.STDOUT ) p_sweep = subprocess.Popen( [act.vars['gfix'], '-sweep', '-user', act.db.user, '-password', act.db.password, act.db.dsn],
stdout = f_sweep_log,
stderr = subprocess.STDOUT
)
##########################################################################
# LOOP-1: WAIT FOR FIRST APPEARANCE OF GFIX PROCESS IN THE MON$ATTACHMENTS
##########################################################################
while True: while True:
t2=py_dt.datetime.now() t2=py_dt.datetime.now()
d1=t2-t1 d1=t2-t1
@ -176,53 +187,83 @@ def test_1(act: Action, sweep_log: Path, capsys):
else: else:
time.sleep(0.1) time.sleep(0.1)
#<while True (loop for search gfix process in mon$attachments) #<while True (loop for search gfix process in mon$attachments)
#< with con.cursor() as cur #< with con.cursor() as cur
#assert sweep_attach_id is None, f'attacment_id of SWEEP process is {sweep_attach_id}' #assert sweep_attach_id is None, f'attacment_id of SWEEP process is {sweep_attach_id}'
assert sweep_attach_id, 'attacment_id of SWEEP process was not found.' assert sweep_attach_id, 'attacment_id of SWEEP process was not found.'
# Let sweep to have some 'useful work':
#
time.sleep(1)
# Now we can KILL attachment that belongs to SWEEP process, <sweep_attach_id>: # Now we can KILL attachment that belongs to SWEEP process, <sweep_attach_id>:
con.execute_immediate(f'delete from mon$attachments where mon$attachment_id = {sweep_attach_id}') con.execute_immediate(f'delete from mon$attachments where mon$attachment_id = {sweep_attach_id}')
p_sweep.wait() p_sweep.wait()
f_sweep_log.close() f_sweep_log.close()
con.commit() assert p_sweep.returncode == 1, 'p_sweep.returncode: {p_sweep.returncode}'
##################################################################################################
# LOOP-2: WAIT FOR POSSIBLE SECOND APPEARENCE (RECONNECT) OF GFIX. IF IT OCCURS THEN WE HAVE A BUG
##################################################################################################
ps = cur.prepare( stm.replace('select ', 'select /* search re-connect that could be made */ ') )
t1=py_dt.datetime.now()
with con.cursor() as cur: with con.cursor() as cur:
cur.execute( stm.replace('select ', 'select /* search re-connect that could be made */ ') ) while True:
t2=py_dt.datetime.now()
d1=t2-t1
dd = d1.seconds*1000 + d1.microseconds//1000
if dd > MAX_WAIT_FOR_GFIX_RESTART_MS:
# Expected: gfix reconnect was not detected for last {MAX_WAIT_FOR_GFIX_RESTART_MS} ms.
break
con.commit()
cur.execute(ps)
# Resultset now must be EMPTY. we must not find any record! # Resultset now must be EMPTY. we must not find any record!
for r in cur: for r in cur:
sweep_reconnect = r[0] sweep_reconnect = r[0]
#con.commit()
if sweep_reconnect:
# UNEXPECTED: gfix reconnect found, with attach_id={sweep_reconnect}
break
else:
time.sleep(0.1)
assert sweep_reconnect is None, f'Found re-connect of SWEEP process, attachment: {sweep_reconnect}' assert sweep_reconnect is None, f'Found re-connect of SWEEP process, attachment: {sweep_reconnect}'
#< with db.connect as con #< with db.connect as con
time.sleep(1) # do NOT remove otherwise log of failed sweep can remain empty
#--------------------------------------------------------------- #---------------------------------------------------------------
# Check-1: log of sweep must contain text: 'connection shutdown': # DISABLED 25.09.2022. SWEEP log can remain empty (4.0.1.2692 Classic)
for line in sweep_log.read_text().splitlines(): ## Check-1: log of sweep must contain text: 'connection shutdown':
if line: #for line in sweep_log.read_text().splitlines():
print('SWEEP LOG:', line.upper()) # if line:
# print('SWEEP LOG:', line.upper())
act.expected_stdout = 'sweep log: connection shutdown'.upper() #
act.stdout = capsys.readouterr().out #act.expected_stdout = 'sweep log: connection shutdown'.upper()
assert act.clean_stdout == act.clean_expected_stdout #act.stdout = capsys.readouterr().out
act.reset() #assert act.clean_stdout == act.clean_expected_stdout
#act.reset()
#--------------------------------------------------------------- #---------------------------------------------------------------
# Trace log # Trace log
found_sweep_failed = 0 found_sweep_failed = 0
p_sweep_failed = re.compile( r'[.*\s+]*20\d{2}(-\d{2}){2}T\d{2}(:\d{2}){2}.\d{3,4}\s+\(.+\)\s+SWEEP_FAILED$', re.IGNORECASE) p_sweep_failed = re.compile( r'[.*\s+]*20\d{2}(-\d{2}){2}T\d{2}(:\d{2}){2}.\d{3,4}\s+\(.+\)\s+SWEEP_FAILED$', re.IGNORECASE)
p_att_success = re.compile( r'[.*\s+]*20\d{2}(-\d{2}){2}T\d{2}(:\d{2}){2}.\d{3,4}\s+\(.+\)\s+ATTACH_DATABASE$', re.IGNORECASE)
trace_expected = 'FOUND SWEEP_FAILED MESSAGE.' trace_expected = 'FOUND SWEEP_FAILED MESSAGE.'
for line in act.trace_log: for i,line in enumerate(act.trace_log):
if line.strip(): if line.strip():
if p_sweep_failed.search(line.strip()): if p_sweep_failed.search(line.strip()):
print(trace_expected) print(trace_expected)
found_sweep_failed = 1 found_sweep_failed = 1
if found_sweep_failed == 1 and ('ATTACH_DATABASE' in line): if found_sweep_failed == 1 and p_att_success.search(line) and i < len(act.trace_log)-2 and 'gfix' in act.trace_log[i+2].lower():
print('TRACE: ATTACH DETECTED AFTER SWEEP FAILED! ') # NB: we have to ignore "FAILED ATTACH_DATABASE".
# It can occur in some cases.
print('TRACE: UNEXPECTED ATTACH FOUND AFTER KILL SWEEP! CHECK LINE N {i}:')
print('TRACE_LOG: ' + line) print('TRACE_LOG: ' + line)
act.expected_stdout = trace_expected act.expected_stdout = trace_expected