2 @message |
assert
checked_mode: table, STDLOG: Records affected: 5
checked_mode: table, STDLOG: ID X
checked_mode: table, STDLOG:
checked_mode: table, STDLOG: -3 -3
checked_mode: table, STDLOG: -2 -2
checked_mode: table, STDLOG: -1 -1
checked_mode: table, STDLOG: 12 12
checked_mode: table, STDLOG: 13 13
checked_mode: table, STDLOG: Records affected: 5
checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: table, STDLOG:
- checked_mode: table, STDLOG: 1 UPD 1
+ checked_mode: table, STDLOG: 1UPD 1
- checked_mode: table, STDLOG: 2 UPD 1
+ checked_mode: table, STDLOG: 2UPD 1
- checked_mode: table, STDLOG: -13 UPD 2
+ checked_mode: table, STDLOG: -13UPD 2
- checked_mode: table, STDLOG: -12 UPD 2
+ checked_mode: table, STDLOG: -12UPD 2
- checked_mode: table, STDLOG: 1 UPD 2
+ checked_mode: table, STDLOG: 1UPD 2
- checked_mode: table, STDLOG: 2 UPD 2
+ checked_mode: table, STDLOG: 2UPD 2
- checked_mode: table, STDLOG: 3 UPD 2
+ checked_mode: table, STDLOG: 3UPD 2
checked_mode: table, STDLOG: Records affected: 7
LOG DETAILS:
2025-07-01 06:04:58.963
2025-07-01 06:04:58.971 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-01 06:04:58.978 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12480/tmp_worker.sql')
2025-07-01 06:04:58.989 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12480/tmp_worker.log')
2025-07-01 06:04:58.999 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12480/tmp_worker.err')
2025-07-01 06:04:59.006 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-01 06:04:59.015
2025-07-01 06:04:59.026 @pytest.mark.trace
2025-07-01 06:04:59.035 @pytest.mark.version('>=4.0.2')
2025-07-01 06:04:59.042 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-01 06:04:59.049 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-01 06:04:59.054
2025-07-01 06:04:59.060 for checked_mode in('table', 'view'):
2025-07-01 06:04:59.066 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-01 06:04:59.071
2025-07-01 06:04:59.083 SQL_TO_BE_RESTARTED = f"""
2025-07-01 06:04:59.091 merge /* {SQL_TAG_THAT_WE_WAITING_FOR} */ into {target_obj} t
2025-07-01 06:04:59.100 using (select * from {target_obj} order by id ROWS 10) s on s.id=t.id
2025-07-01 06:04:59.107 when matched then
2025-07-01 06:04:59.113 update set t.id = -t.id, t.x = -s.x
2025-07-01 06:04:59.120 when not matched then
2025-07-01 06:04:59.127 insert(id,x) values(s.id, -s.x - 500)
2025-07-01 06:04:59.133 """
2025-07-01 06:04:59.138
2025-07-01 06:04:59.143 # add rows with ID = 1, 2, 3:
2025-07-01 06:04:59.149 sql_addi = f'''
2025-07-01 06:04:59.156 set term ^;
2025-07-01 06:04:59.162 execute block as
2025-07-01 06:04:59.171 begin
2025-07-01 06:04:59.179 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-01 06:04:59.186 end
2025-07-01 06:04:59.192 ^
2025-07-01 06:04:59.198 set term ;^
2025-07-01 06:04:59.204 insert into {target_obj}(id, x)
2025-07-01 06:04:59.210 select row_number()over(),row_number()over()
2025-07-01 06:04:59.216 from rdb$types rows 3;
2025-07-01 06:04:59.222 commit;
2025-07-01 06:04:59.228 '''
2025-07-01 06:04:59.235
2025-07-01 06:04:59.246 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-07-01 06:04:59.253 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-01 06:04:59.259 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-01 06:04:59.265 assert act.stderr == ''
2025-07-01 06:04:59.274 act.reset()
2025-07-01 06:04:59.280
2025-07-01 06:04:59.286 trace_cfg_items = [
2025-07-01 06:04:59.293 'time_threshold = 0',
2025-07-01 06:04:59.305 'log_errors = true',
2025-07-01 06:04:59.315 'log_statement_start = true',
2025-07-01 06:04:59.324 'log_statement_finish = true',
2025-07-01 06:04:59.331 ]
2025-07-01 06:04:59.343
2025-07-01 06:04:59.353 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-01 06:04:59.360
2025-07-01 06:04:59.366 with act.db.connect() as con_lock_1, act.db.connect() as con_lock_2, act.db.connect() as con_monitoring:
2025-07-01 06:04:59.372
2025-07-01 06:04:59.381 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-01 06:04:59.389 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-01 06:04:59.395 cur_monitoring = tx_monitoring.cursor()
2025-07-01 06:04:59.403
2025-07-01 06:04:59.414 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-01 06:04:59.422 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-01 06:04:59.429 c.execute_immediate(sttm)
2025-07-01 06:04:59.435
2025-07-01 06:04:59.442 #########################
2025-07-01 06:04:59.450 ### L O C K E R - 1 ###
2025-07-01 06:04:59.460 #########################
2025-07-01 06:04:59.468
2025-07-01 06:04:59.475 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = 3' )
2025-07-01 06:04:59.480
2025-07-01 06:04:59.485 worker_sql = f'''
2025-07-01 06:04:59.491 set list on;
2025-07-01 06:04:59.497 set autoddl off;
2025-07-01 06:04:59.503 set term ^;
2025-07-01 06:04:59.511 execute block returns (whoami varchar(30)) as
2025-07-01 06:04:59.520 begin
2025-07-01 06:04:59.530 whoami = 'WORKER'; -- , ATT#' || current_connection;
2025-07-01 06:04:59.538 rdb$set_context('USER_SESSION','WHO', whoami);
2025-07-01 06:04:59.544 -- suspend;
2025-07-01 06:04:59.557 end
2025-07-01 06:04:59.565 ^
2025-07-01 06:04:59.572 set term ;^
2025-07-01 06:04:59.578 commit;
2025-07-01 06:04:59.583 SET KEEP_TRAN_PARAMS ON;
2025-07-01 06:04:59.588 set transaction read committed read consistency;
2025-07-01 06:04:59.594
2025-07-01 06:04:59.599 set list off;
2025-07-01 06:04:59.605 set wng off;
2025-07-01 06:04:59.611 set count on;
2025-07-01 06:04:59.619
2025-07-01 06:04:59.630 -- THIS MUST HANG:
2025-07-01 06:04:59.638 {SQL_TO_BE_RESTARTED};
2025-07-01 06:04:59.643
2025-07-01 06:04:59.649 -- check results:
2025-07-01 06:04:59.654 -- ###############
2025-07-01 06:04:59.659 select id,x from {target_obj} order by id; -- this will produce output only after all lockers do their commit/rollback
2025-07-01 06:04:59.664
2025-07-01 06:04:59.670 select v.old_id, v.op, v.snap_no_rank
2025-07-01 06:04:59.676 from v_worker_log v
2025-07-01 06:04:59.681 where v.op = 'upd';
2025-07-01 06:04:59.687
2025-07-01 06:04:59.699 set width who 10;
2025-07-01 06:04:59.710 -- DO NOT check this! Values can differ here from one run to another!
2025-07-01 06:04:59.719 -- select id, trn, who, old_id, new_id, op, rec_vers, global_cn, snap_no from tlog_done order by id;
2025-07-01 06:04:59.725
2025-07-01 06:04:59.733 rollback;
2025-07-01 06:04:59.741
2025-07-01 06:04:59.747 '''
2025-07-01 06:04:59.753
2025-07-01 06:04:59.759 fn_worker_sql.write_text(worker_sql)
2025-07-01 06:04:59.765
2025-07-01 06:04:59.771 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-01 06:04:59.777
2025-07-01 06:04:59.783 ############################################################################
2025-07-01 06:04:59.790 ### L A U N C H W O R K E R U S I N G I S Q L, A S Y N C. ###
2025-07-01 06:04:59.796 ############################################################################
2025-07-01 06:04:59.810 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-01 06:04:59.821 '-user', act.db.user,
2025-07-01 06:04:59.834 '-password', act.db.password,
2025-07-01 06:04:59.846 '-pag', '9999999',
2025-07-01 06:04:59.856 act.db.dsn
2025-07-01 06:04:59.864 ],
2025-07-01 06:04:59.872 stdout = hang_out,
2025-07-01 06:04:59.878 stderr = hang_err
2025-07-01 06:04:59.885 )
2025-07-01 06:04:59.897 # NB: when ISQL will establish attach, first record that it must lock is ID = 1 -- see above SQL_TO_BE_RESTARTED
2025-07-01 06:04:59.909 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:04:59.919 #
2025-07-01 06:04:59.927 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=1', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:04:59.940
2025-07-01 06:04:59.951 #########################
2025-07-01 06:04:59.961 ### L O C K E R - 2 ###
2025-07-01 06:04:59.969 #########################
2025-07-01 06:04:59.982 con_lock_2.execute_immediate( f'insert into {target_obj}(id,x) values(-13,-13)')
2025-07-01 06:04:59.991 con_lock_2.commit()
2025-07-01 06:05:00.003 con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = -13')
2025-07-01 06:05:00.013
2025-07-01 06:05:00.024 #########################
2025-07-01 06:05:00.032 ### L O C K E R - 1 ###
2025-07-01 06:05:00.040 #########################
2025-07-01 06:05:00.047 con_lock_1.commit() # releases record with ID = 3 ==> now it can be locked by worker.
2025-07-01 06:05:00.055
2025-07-01 06:05:00.067 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 3.
2025-07-01 06:05:00.076 #
2025-07-01 06:05:00.084 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=3', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:05:00.093 # If we come here then it means that record with ID = 3 for sure is locked by WORKER.
2025-07-01 06:05:00.106
2025-07-01 06:05:00.117 con_lock_1.execute_immediate( f'insert into {target_obj}(id,x) values(-12,-12)' )
2025-07-01 06:05:00.128 con_lock_1.commit()
2025-07-01 06:05:00.138 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = -12' )
2025-07-01 06:05:00.147
2025-07-01 06:05:00.159 #########################
2025-07-01 06:05:00.171 ### L O C K E R - 2 ###
2025-07-01 06:05:00.180 #########################
2025-07-01 06:05:00.188 con_lock_2.commit() # releases record with ID = -13 ==> now it can be locked by worker.
2025-07-01 06:05:00.194
2025-07-01 06:05:00.201 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = -13.
2025-07-01 06:05:00.207 #
2025-07-01 06:05:00.214 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=-13', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:05:00.221 # If we come here then it means that record with ID = -13 for sure is locked by WORKER.
2025-07-01 06:05:00.227
2025-07-01 06:05:00.234 #########################
2025-07-01 06:05:00.245 ### L O C K E R - 1 ###
2025-07-01 06:05:00.256 #########################
2025-07-01 06:05:00.268 con_lock_1.commit() # WORKER will complete his job after this
2025-07-01 06:05:00.278
2025-07-01 06:05:00.288 # Here we wait for ISQL complete its mission:
2025-07-01 06:05:00.297 p_worker.wait()
2025-07-01 06:05:00.304
2025-07-01 06:05:00.310 #< with act.db.connect()
2025-07-01 06:05:00.317
2025-07-01 06:05:00.323 for g in (fn_worker_log, fn_worker_err):
2025-07-01 06:05:00.331 with g.open() as f:
2025-07-01 06:05:00.347 for line in f:
2025-07-01 06:05:00.361 if line.split():
2025-07-01 06:05:00.371 if g == fn_worker_log:
2025-07-01 06:05:00.383 print(f'checked_mode: {checked_mode}, STDLOG: {line}')
2025-07-01 06:05:00.393 else:
2025-07-01 06:05:00.401 print(f'UNEXPECTED STDERR {line}')
2025-07-01 06:05:00.407
2025-07-01 06:05:00.415 expected_stdout_worker = f"""
2025-07-01 06:05:00.427 checked_mode: {checked_mode}, STDLOG: Records affected: 5
2025-07-01 06:05:00.434
2025-07-01 06:05:00.443 checked_mode: {checked_mode}, STDLOG: ID X
2025-07-01 06:05:00.452 checked_mode: {checked_mode}, STDLOG: ======= =======
2025-07-01 06:05:00.459 checked_mode: {checked_mode}, STDLOG: -3 -3
2025-07-01 06:05:00.468 checked_mode: {checked_mode}, STDLOG: -2 -2
2025-07-01 06:05:00.480 checked_mode: {checked_mode}, STDLOG: -1 -1
2025-07-01 06:05:00.494 checked_mode: {checked_mode}, STDLOG: 12 12
2025-07-01 06:05:00.506 checked_mode: {checked_mode}, STDLOG: 13 13
2025-07-01 06:05:00.514 checked_mode: {checked_mode}, STDLOG: Records affected: 5
2025-07-01 06:05:00.520
2025-07-01 06:05:00.527 checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:05:00.534 checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
2025-07-01 06:05:00.546 checked_mode: {checked_mode}, STDLOG: 1 UPD 1
2025-07-01 06:05:00.559 checked_mode: {checked_mode}, STDLOG: 2 UPD 1
2025-07-01 06:05:00.570 checked_mode: {checked_mode}, STDLOG: -13 UPD 2
2025-07-01 06:05:00.579 checked_mode: {checked_mode}, STDLOG: -12 UPD 2
2025-07-01 06:05:00.587 checked_mode: {checked_mode}, STDLOG: 1 UPD 2
2025-07-01 06:05:00.596 checked_mode: {checked_mode}, STDLOG: 2 UPD 2
2025-07-01 06:05:00.606 checked_mode: {checked_mode}, STDLOG: 3 UPD 2
2025-07-01 06:05:00.614
2025-07-01 06:05:00.623 checked_mode: {checked_mode}, STDLOG: Records affected: 7
2025-07-01 06:05:00.630 """
2025-07-01 06:05:00.637
2025-07-01 06:05:00.643 act.expected_stdout = expected_stdout_worker
2025-07-01 06:05:00.649 act.stdout = capsys.readouterr().out
2025-07-01 06:05:00.655 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-01 06:05:00.661 E assert
2025-07-01 06:05:00.673 E checked_mode: table, STDLOG: Records affected: 5
2025-07-01 06:05:00.680 E checked_mode: table, STDLOG: ID X
2025-07-01 06:05:00.687 E checked_mode: table, STDLOG:
2025-07-01 06:05:00.699 E checked_mode: table, STDLOG: -3 -3
2025-07-01 06:05:00.707 E checked_mode: table, STDLOG: -2 -2
2025-07-01 06:05:00.714 E checked_mode: table, STDLOG: -1 -1
2025-07-01 06:05:00.723 E checked_mode: table, STDLOG: 12 12
2025-07-01 06:05:00.734 E checked_mode: table, STDLOG: 13 13
2025-07-01 06:05:00.741 E checked_mode: table, STDLOG: Records affected: 5
2025-07-01 06:05:00.748 E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:05:00.754 E checked_mode: table, STDLOG:
2025-07-01 06:05:00.761 E - checked_mode: table, STDLOG: 1 UPD 1
2025-07-01 06:05:00.776 E + checked_mode: table, STDLOG: 1UPD 1
2025-07-01 06:05:00.783 E - checked_mode: table, STDLOG: 2 UPD 1
2025-07-01 06:05:00.796 E + checked_mode: table, STDLOG: 2UPD 1
2025-07-01 06:05:00.809 E - checked_mode: table, STDLOG: -13 UPD 2
2025-07-01 06:05:00.824 E + checked_mode: table, STDLOG: -13UPD 2
2025-07-01 06:05:00.830 E - checked_mode: table, STDLOG: -12 UPD 2
2025-07-01 06:05:00.842 E + checked_mode: table, STDLOG: -12UPD 2
2025-07-01 06:05:00.848 E - checked_mode: table, STDLOG: 1 UPD 2
2025-07-01 06:05:00.861 E + checked_mode: table, STDLOG: 1UPD 2
2025-07-01 06:05:00.867 E - checked_mode: table, STDLOG: 2 UPD 2
2025-07-01 06:05:00.879 E + checked_mode: table, STDLOG: 2UPD 2
2025-07-01 06:05:00.885 E - checked_mode: table, STDLOG: 3 UPD 2
2025-07-01 06:05:00.897 E + checked_mode: table, STDLOG: 3UPD 2
2025-07-01 06:05:00.903 E checked_mode: table, STDLOG: Records affected: 7
2025-07-01 06:05:00.909
2025-07-01 06:05:00.915 tests/functional/transactions/test_read_consist_sttm_restart_on_merge_01.py:429: AssertionError
2025-07-01 06:05:00.921 ---------------------------- Captured stdout setup -----------------------------
2025-07-01 06:05:00.927 Creating db: localhost:/var/tmp/qa_2024/test_12480/test.fdb [page_size=None, sql_dialect=None, charset='NONE', user=SYSDBA, password=masterkey]
|
3 #text |
act = <firebird.qa.plugin.Action pytest object at [hex]>
fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12480/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12480/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12480/tmp_worker.err')
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>
@pytest.mark.trace
@pytest.mark.version('>=4.0.2')
def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
for checked_mode in('table', 'view'):
target_obj = 'test' if checked_mode == 'table' else 'v_test'
SQL_TO_BE_RESTARTED = f"""
merge /* {SQL_TAG_THAT_WE_WAITING_FOR} */ into {target_obj} t
using (select * from {target_obj} order by id ROWS 10) s on s.id=t.id
when matched then
update set t.id = -t.id, t.x = -s.x
when not matched then
insert(id,x) values(s.id, -s.x - 500)
"""
# add rows with ID = 1, 2, 3:
sql_addi = f'''
set term ^;
execute block as
begin
rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
end
^
set term ;^
insert into {target_obj}(id, x)
select row_number()over(),row_number()over()
from rdb$types rows 3;
commit;
'''
act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
# ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
# See also letter from dimitr, 01-feb-2022 14:46
assert act.stderr == ''
act.reset()
trace_cfg_items = [
'time_threshold = 0',
'log_errors = true',
'log_statement_start = true',
'log_statement_finish = true',
]
with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
with act.db.connect() as con_lock_1, act.db.connect() as con_lock_2, act.db.connect() as con_monitoring:
tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
cur_monitoring = tx_monitoring.cursor()
for i,c in enumerate((con_lock_1,con_lock_2)):
sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
c.execute_immediate(sttm)
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = 3' )
worker_sql = f'''
set list on;
set autoddl off;
set term ^;
execute block returns (whoami varchar(30)) as
begin
whoami = 'WORKER'; -- , ATT#' || current_connection;
rdb$set_context('USER_SESSION','WHO', whoami);
-- suspend;
end
^
set term ;^
commit;
SET KEEP_TRAN_PARAMS ON;
set transaction read committed read consistency;
set list off;
set wng off;
set count on;
-- THIS MUST HANG:
{SQL_TO_BE_RESTARTED};
-- check results:
-- ###############
select id,x from {target_obj} order by id; -- this will produce output only after all lockers do their commit/rollback
select v.old_id, v.op, v.snap_no_rank
from v_worker_log v
where v.op = 'upd';
set width who 10;
-- DO NOT check this! Values can differ here from one run to another!
-- select id, trn, who, old_id, new_id, op, rec_vers, global_cn, snap_no from tlog_done order by id;
rollback;
'''
fn_worker_sql.write_text(worker_sql)
with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
############################################################################
### L A U N C H W O R K E R U S I N G I S Q L, A S Y N C. ###
############################################################################
p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
'-user', act.db.user,
'-password', act.db.password,
'-pag', '9999999',
act.db.dsn
],
stdout = hang_out,
stderr = hang_err
)
# NB: when ISQL will establish attach, first record that it must lock is ID = 1 -- see above SQL_TO_BE_RESTARTED
# We must to ensure that this (worker) attachment has been really created and LOCKS this record:
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=1', SQL_TAG_THAT_WE_WAITING_FOR)
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.execute_immediate( f'insert into {target_obj}(id,x) values(-13,-13)')
con_lock_2.commit()
con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = -13')
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # releases record with ID = 3 ==> now it can be locked by worker.
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = 3.
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=3', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = 3 for sure is locked by WORKER.
con_lock_1.execute_immediate( f'insert into {target_obj}(id,x) values(-12,-12)' )
con_lock_1.commit()
con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = -12' )
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.commit() # releases record with ID = -13 ==> now it can be locked by worker.
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = -13.
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=-13', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = -13 for sure is locked by WORKER.
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # WORKER will complete his job after this
# Here we wait for ISQL complete its mission:
p_worker.wait()
#< with act.db.connect()
for g in (fn_worker_log, fn_worker_err):
with g.open() as f:
for line in f:
if line.split():
if g == fn_worker_log:
print(f'checked_mode: {checked_mode}, STDLOG: {line}')
else:
print(f'UNEXPECTED STDERR {line}')
expected_stdout_worker = f"""
checked_mode: {checked_mode}, STDLOG: Records affected: 5
checked_mode: {checked_mode}, STDLOG: ID X
checked_mode: {checked_mode}, STDLOG: ======= =======
checked_mode: {checked_mode}, STDLOG: -3 -3
checked_mode: {checked_mode}, STDLOG: -2 -2
checked_mode: {checked_mode}, STDLOG: -1 -1
checked_mode: {checked_mode}, STDLOG: 12 12
checked_mode: {checked_mode}, STDLOG: 13 13
checked_mode: {checked_mode}, STDLOG: Records affected: 5
checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, STDLOG: 1 UPD 1
checked_mode: {checked_mode}, STDLOG: 2 UPD 1
checked_mode: {checked_mode}, STDLOG: -13 UPD 2
checked_mode: {checked_mode}, STDLOG: -12 UPD 2
checked_mode: {checked_mode}, STDLOG: 1 UPD 2
checked_mode: {checked_mode}, STDLOG: 2 UPD 2
checked_mode: {checked_mode}, STDLOG: 3 UPD 2
checked_mode: {checked_mode}, STDLOG: Records affected: 7
"""
act.expected_stdout = expected_stdout_worker
act.stdout = capsys.readouterr().out
> assert act.clean_stdout == act.clean_expected_stdout
E assert
E checked_mode: table, STDLOG: Records affected: 5
E checked_mode: table, STDLOG: ID X
E checked_mode: table, STDLOG:
E checked_mode: table, STDLOG: -3 -3
E checked_mode: table, STDLOG: -2 -2
E checked_mode: table, STDLOG: -1 -1
E checked_mode: table, STDLOG: 12 12
E checked_mode: table, STDLOG: 13 13
E checked_mode: table, STDLOG: Records affected: 5
E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
E checked_mode: table, STDLOG:
E - checked_mode: table, STDLOG: 1 UPD 1
E + checked_mode: table, STDLOG: 1UPD 1
E - checked_mode: table, STDLOG: 2 UPD 1
E + checked_mode: table, STDLOG: 2UPD 1
E - checked_mode: table, STDLOG: -13 UPD 2
E + checked_mode: table, STDLOG: -13UPD 2
E - checked_mode: table, STDLOG: -12 UPD 2
E + checked_mode: table, STDLOG: -12UPD 2
E - checked_mode: table, STDLOG: 1 UPD 2
E + checked_mode: table, STDLOG: 1UPD 2
E - checked_mode: table, STDLOG: 2 UPD 2
E + checked_mode: table, STDLOG: 2UPD 2
E - checked_mode: table, STDLOG: 3 UPD 2
E + checked_mode: table, STDLOG: 3UPD 2
E checked_mode: table, STDLOG: Records affected: 7
tests/functional/transactions/test_read_consist_sttm_restart_on_merge_01.py:429: AssertionError
|