2 @message |
assert
checked_mode: table, STDLOG: Records affected: 6
checked_mode: table, STDLOG: ID
checked_mode: table, STDLOG:
checked_mode: table, STDLOG: 1
checked_mode: table, STDLOG: 2
checked_mode: table, STDLOG: Records affected: 2
checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: table, STDLOG:
- checked_mode: table, STDLOG: 3 DEL 1
+ checked_mode: table, STDLOG: 3DEL 1
- checked_mode: table, STDLOG: 4 DEL 1
+ checked_mode: table, STDLOG: 4DEL 1
- checked_mode: table, STDLOG: -3 DEL 2
+ checked_mode: table, STDLOG: -3DEL 2
- checked_mode: table, STDLOG: -2 DEL 2
+ checked_mode: table, STDLOG: -2DEL 2
- checked_mode: table, STDLOG: -1 DEL 2
+ checked_mode: table, STDLOG: -1DEL 2
- checked_mode: table, STDLOG: 3 DEL 2
+ checked_mode: table, STDLOG: 3DEL 2
- checked_mode: table, STDLOG: 4 DEL 2
+ checked_mode: table, STDLOG: 4DEL 2
- checked_mode: table, STDLOG: 5 DEL 2
+ checked_mode: table, STDLOG: 5DEL 2
checked_mode: table, STDLOG: Records affected: 8
LOG DETAILS:
2025-07-02 06:07:47.000
2025-07-02 06:07:47.006 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-02 06:07:47.011 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12482/tmp_worker.sql')
2025-07-02 06:07:47.016 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12482/tmp_worker.log')
2025-07-02 06:07:47.020 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12482/tmp_worker.err')
2025-07-02 06:07:47.025 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-02 06:07:47.030
2025-07-02 06:07:47.034 @pytest.mark.trace
2025-07-02 06:07:47.039 @pytest.mark.version('>=4.0.2')
2025-07-02 06:07:47.044 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-02 06:07:47.049 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-02 06:07:47.053
2025-07-02 06:07:47.058 for checked_mode in('table', 'view'):
2025-07-02 06:07:47.062 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-02 06:07:47.067
2025-07-02 06:07:47.071 SQL_TO_BE_RESTARTED = f"""
2025-07-02 06:07:47.076 merge /* {SQL_TAG_THAT_WE_WAITING_FOR} */ into {target_obj} t
2025-07-02 06:07:47.081 using(select * from {target_obj} where id < 0 or id >= 3 order by id) s on t.id = s.id
2025-07-02 06:07:47.086 when matched then
2025-07-02 06:07:47.090 DELETE
2025-07-02 06:07:47.095 """
2025-07-02 06:07:47.099 # add rows with ID = 1,2,3,4,5:
2025-07-02 06:07:47.104 sql_addi = f'''
2025-07-02 06:07:47.109 set term ^;
2025-07-02 06:07:47.113 execute block as
2025-07-02 06:07:47.118 begin
2025-07-02 06:07:47.123 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-02 06:07:47.128 end
2025-07-02 06:07:47.132 ^
2025-07-02 06:07:47.137 set term ;^
2025-07-02 06:07:47.142 insert into {target_obj}(id, x)
2025-07-02 06:07:47.146 select row_number()over(),row_number()over()
2025-07-02 06:07:47.151 from rdb$types rows 5;
2025-07-02 06:07:47.156 commit;
2025-07-02 06:07:47.161 '''
2025-07-02 06:07:47.166
2025-07-02 06:07:47.170 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-07-02 06:07:47.175 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-02 06:07:47.180 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-02 06:07:47.184 assert act.stderr == ''
2025-07-02 06:07:47.190 act.reset()
2025-07-02 06:07:47.196
2025-07-02 06:07:47.200 trace_cfg_items = [
2025-07-02 06:07:47.206 'time_threshold = 0',
2025-07-02 06:07:47.213 'log_errors = true',
2025-07-02 06:07:47.225 'log_statement_start = true',
2025-07-02 06:07:47.237 'log_statement_finish = true',
2025-07-02 06:07:47.245 ]
2025-07-02 06:07:47.254
2025-07-02 06:07:47.266 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-02 06:07:47.277
2025-07-02 06:07:47.289 with act.db.connect() as con_lock_1, act.db.connect() as con_lock_2, act.db.connect() as con_monitoring:
2025-07-02 06:07:47.299
2025-07-02 06:07:47.308 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-02 06:07:47.320 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-02 06:07:47.331 cur_monitoring = tx_monitoring.cursor()
2025-07-02 06:07:47.339
2025-07-02 06:07:47.347 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-02 06:07:47.355 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-02 06:07:47.362 c.execute_immediate(sttm)
2025-07-02 06:07:47.374
2025-07-02 06:07:47.387 #########################
2025-07-02 06:07:47.396 ### L O C K E R - 1 ###
2025-07-02 06:07:47.403 #########################
2025-07-02 06:07:47.411
2025-07-02 06:07:47.419 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = 5' )
2025-07-02 06:07:47.426
2025-07-02 06:07:47.432 worker_sql = f'''
2025-07-02 06:07:47.439 set list on;
2025-07-02 06:07:47.447 set autoddl off;
2025-07-02 06:07:47.455 set term ^;
2025-07-02 06:07:47.464 execute block returns (whoami varchar(30)) as
2025-07-02 06:07:47.472 begin
2025-07-02 06:07:47.481 whoami = 'WORKER'; -- , ATT#' || current_connection;
2025-07-02 06:07:47.489 rdb$set_context('USER_SESSION','WHO', whoami);
2025-07-02 06:07:47.499 -- suspend;
2025-07-02 06:07:47.504 end
2025-07-02 06:07:47.517 ^
2025-07-02 06:07:47.529 set term ;^
2025-07-02 06:07:47.541 commit;
2025-07-02 06:07:47.554 --set echo on;
2025-07-02 06:07:47.568 SET KEEP_TRAN_PARAMS ON;
2025-07-02 06:07:47.579 set transaction read committed read consistency;
2025-07-02 06:07:47.588 set list off;
2025-07-02 06:07:47.595 set wng off;
2025-07-02 06:07:47.600 set count on;
2025-07-02 06:07:47.605
2025-07-02 06:07:47.611 -- MUST HANG:
2025-07-02 06:07:47.617 {SQL_TO_BE_RESTARTED};
2025-07-02 06:07:47.623
2025-07-02 06:07:47.630 -- check results:
2025-07-02 06:07:47.636 -- ###############
2025-07-02 06:07:47.642 select id from {target_obj} order by id; -- this will produce output only after all lockers do their commit/rollback
2025-07-02 06:07:47.648
2025-07-02 06:07:47.654 select v.old_id, v.op, v.snap_no_rank
2025-07-02 06:07:47.661 from v_worker_log v
2025-07-02 06:07:47.667 where v.op = 'del';
2025-07-02 06:07:47.674
2025-07-02 06:07:47.685 set width who 10;
2025-07-02 06:07:47.694 -- DO NOT check this! Values can differ here from one run to another!
2025-07-02 06:07:47.702 -- select id, trn, who, old_id, new_id, op, rec_vers, global_cn, snap_no from tlog_done order by id;
2025-07-02 06:07:47.713
2025-07-02 06:07:47.727 rollback;
2025-07-02 06:07:47.737
2025-07-02 06:07:47.752 '''
2025-07-02 06:07:47.763
2025-07-02 06:07:47.771 fn_worker_sql.write_text(worker_sql)
2025-07-02 06:07:47.779
2025-07-02 06:07:47.795 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-02 06:07:47.804
2025-07-02 06:07:47.813 ############################################################################
2025-07-02 06:07:47.821 ### 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-02 06:07:47.828 ############################################################################
2025-07-02 06:07:47.835 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-02 06:07:47.844 '-user', act.db.user,
2025-07-02 06:07:47.852 '-password', act.db.password,
2025-07-02 06:07:47.862 '-pag', '9999999',
2025-07-02 06:07:47.869 act.db.dsn
2025-07-02 06:07:47.876 ],
2025-07-02 06:07:47.882 stdout = hang_out,
2025-07-02 06:07:47.891 stderr = hang_err
2025-07-02 06:07:47.903 )
2025-07-02 06:07:47.912 # NB: when ISQL will establish attach, first record that it must lock is ID = 3 -- see above SQL_TO_BE_RESTARTED
2025-07-02 06:07:47.923 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-02 06:07:47.937 #
2025-07-02 06:07:47.952 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-02 06:07:47.963
2025-07-02 06:07:47.976
2025-07-02 06:07:47.987 #########################
2025-07-02 06:07:47.995 ### L O C K E R - 2 ###
2025-07-02 06:07:48.001 #########################
2025-07-02 06:07:48.008 # Insert ID value that is less than previous min(id).
2025-07-02 06:07:48.017 # Session-worker is executing its statement using PLAN ORDER,
2025-07-02 06:07:48.030 # and it should see this new value and restart its statement:
2025-07-02 06:07:48.040 con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(-1)' )
2025-07-02 06:07:48.053 con_lock_2.commit()
2025-07-02 06:07:48.066 con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = -1' )
2025-07-02 06:07:48.077
2025-07-02 06:07:48.085 #########################
2025-07-02 06:07:48.096 ### L O C K E R - 1 ###
2025-07-02 06:07:48.109 #########################
2025-07-02 06:07:48.118 con_lock_1.commit() # releases record with ID = 5 ==> now it can be locked by worker.
2025-07-02 06:07:48.125
2025-07-02 06:07:48.132 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 5.
2025-07-02 06:07:48.139 #
2025-07-02 06:07:48.147 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=5', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-02 06:07:48.155 # If we come here then it means that record with ID = 5 for sure is locked by WORKER.
2025-07-02 06:07:48.163
2025-07-02 06:07:48.170 con_lock_1.execute_immediate( f'insert into {target_obj}(id) values(-2)' )
2025-07-02 06:07:48.177 con_lock_1.commit()
2025-07-02 06:07:48.184 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = -2' )
2025-07-02 06:07:48.191
2025-07-02 06:07:48.199
2025-07-02 06:07:48.206 #########################
2025-07-02 06:07:48.213 ### L O C K E R - 2 ###
2025-07-02 06:07:48.219 #########################
2025-07-02 06:07:48.224 # Insert ID value that is less than previous min(id).
2025-07-02 06:07:48.229 # Session-worker is executing its statement using PLAN ORDER,
2025-07-02 06:07:48.242 # and it should see this new value and restart its statement:
2025-07-02 06:07:48.251 con_lock_2.commit() # releases record with ID = -1 ==> now it can be locked by worker.
2025-07-02 06:07:48.258
2025-07-02 06:07:48.266 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = -1.
2025-07-02 06:07:48.274 #
2025-07-02 06:07:48.281 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-02 06:07:48.288 # If we come here then it means that record with ID = -1 for sure is locked by WORKER.
2025-07-02 06:07:48.294
2025-07-02 06:07:48.304 con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(-3)' )
2025-07-02 06:07:48.318 con_lock_2.commit()
2025-07-02 06:07:48.329 con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = -3' )
2025-07-02 06:07:48.341
2025-07-02 06:07:48.352 #########################
2025-07-02 06:07:48.361 ### L O C K E R - 1 ###
2025-07-02 06:07:48.369 #########################
2025-07-02 06:07:48.376 con_lock_1.commit() # releases record with ID = -2 ==> now it can be locked by worker.
2025-07-02 06:07:48.383
2025-07-02 06:07:48.391 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = -2.
2025-07-02 06:07:48.399 #
2025-07-02 06:07:48.411 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=-2', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-02 06:07:48.421 # If we come here then it means that record with ID = -2 for sure is locked by WORKER.
2025-07-02 06:07:48.428
2025-07-02 06:07:48.436 con_lock_2.commit()
2025-07-02 06:07:48.448
2025-07-02 06:07:48.462 # Here we wait for ISQL complete its mission:
2025-07-02 06:07:48.473 p_worker.wait()
2025-07-02 06:07:48.481
2025-07-02 06:07:48.489 #< with act.db.connect()
2025-07-02 06:07:48.495
2025-07-02 06:07:48.505 for g in (fn_worker_log, fn_worker_err):
2025-07-02 06:07:48.517 with g.open() as f:
2025-07-02 06:07:48.531 for line in f:
2025-07-02 06:07:48.544 if line.split():
2025-07-02 06:07:48.554 if g == fn_worker_log:
2025-07-02 06:07:48.565 print(f'checked_mode: {checked_mode}, STDLOG: {line}')
2025-07-02 06:07:48.575 else:
2025-07-02 06:07:48.585 print(f'UNEXPECTED STDERR {line}')
2025-07-02 06:07:48.593
2025-07-02 06:07:48.600 expected_stdout_worker = f"""
2025-07-02 06:07:48.607 checked_mode: {checked_mode}, STDLOG: Records affected: 6
2025-07-02 06:07:48.616
2025-07-02 06:07:48.630 checked_mode: {checked_mode}, STDLOG: ID
2025-07-02 06:07:48.641 checked_mode: {checked_mode}, STDLOG: =======
2025-07-02 06:07:48.649 checked_mode: {checked_mode}, STDLOG: 1
2025-07-02 06:07:48.661 checked_mode: {checked_mode}, STDLOG: 2
2025-07-02 06:07:48.673 checked_mode: {checked_mode}, STDLOG: Records affected: 2
2025-07-02 06:07:48.685
2025-07-02 06:07:48.695 checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-02 06:07:48.708 checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
2025-07-02 06:07:48.719 checked_mode: {checked_mode}, STDLOG: 3 DEL 1
2025-07-02 06:07:48.732 checked_mode: {checked_mode}, STDLOG: 4 DEL 1
2025-07-02 06:07:48.744 checked_mode: {checked_mode}, STDLOG: -3 DEL 2
2025-07-02 06:07:48.757 checked_mode: {checked_mode}, STDLOG: -2 DEL 2
2025-07-02 06:07:48.767 checked_mode: {checked_mode}, STDLOG: -1 DEL 2
2025-07-02 06:07:48.775 checked_mode: {checked_mode}, STDLOG: 3 DEL 2
2025-07-02 06:07:48.783 checked_mode: {checked_mode}, STDLOG: 4 DEL 2
2025-07-02 06:07:48.790 checked_mode: {checked_mode}, STDLOG: 5 DEL 2
2025-07-02 06:07:48.799 checked_mode: {checked_mode}, STDLOG: Records affected: 8
2025-07-02 06:07:48.805 """
2025-07-02 06:07:48.812
2025-07-02 06:07:48.820 act.expected_stdout = expected_stdout_worker
2025-07-02 06:07:48.831 act.stdout = capsys.readouterr().out
2025-07-02 06:07:48.840 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-02 06:07:48.853 E assert
2025-07-02 06:07:48.861 E checked_mode: table, STDLOG: Records affected: 6
2025-07-02 06:07:48.869 E checked_mode: table, STDLOG: ID
2025-07-02 06:07:48.876 E checked_mode: table, STDLOG:
2025-07-02 06:07:48.881 E checked_mode: table, STDLOG: 1
2025-07-02 06:07:48.886 E checked_mode: table, STDLOG: 2
2025-07-02 06:07:48.891 E checked_mode: table, STDLOG: Records affected: 2
2025-07-02 06:07:48.895 E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-02 06:07:48.900 E checked_mode: table, STDLOG:
2025-07-02 06:07:48.906 E - checked_mode: table, STDLOG: 3 DEL 1
2025-07-02 06:07:48.918 E + checked_mode: table, STDLOG: 3DEL 1
2025-07-02 06:07:48.924 E - checked_mode: table, STDLOG: 4 DEL 1
2025-07-02 06:07:48.938 E + checked_mode: table, STDLOG: 4DEL 1
2025-07-02 06:07:48.951 E - checked_mode: table, STDLOG: -3 DEL 2
2025-07-02 06:07:48.967 E + checked_mode: table, STDLOG: -3DEL 2
2025-07-02 06:07:48.975 E - checked_mode: table, STDLOG: -2 DEL 2
2025-07-02 06:07:48.992 E + checked_mode: table, STDLOG: -2DEL 2
2025-07-02 06:07:48.999 E - checked_mode: table, STDLOG: -1 DEL 2
2025-07-02 06:07:49.017 E + checked_mode: table, STDLOG: -1DEL 2
2025-07-02 06:07:49.027 E - checked_mode: table, STDLOG: 3 DEL 2
2025-07-02 06:07:49.044 E + checked_mode: table, STDLOG: 3DEL 2
2025-07-02 06:07:49.051 E - checked_mode: table, STDLOG: 4 DEL 2
2025-07-02 06:07:49.070 E + checked_mode: table, STDLOG: 4DEL 2
2025-07-02 06:07:49.081 E - checked_mode: table, STDLOG: 5 DEL 2
2025-07-02 06:07:49.102 E + checked_mode: table, STDLOG: 5DEL 2
2025-07-02 06:07:49.112 E checked_mode: table, STDLOG: Records affected: 8
2025-07-02 06:07:49.124
2025-07-02 06:07:49.137 tests/functional/transactions/test_read_consist_sttm_restart_on_merge_02.py:486: AssertionError
2025-07-02 06:07:49.148 ---------------------------- Captured stdout setup -----------------------------
2025-07-02 06:07:49.154 Creating db: localhost:/var/tmp/qa_2024/test_12482/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_12482/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12482/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12482/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} where id < 0 or id >= 3 order by id) s on t.id = s.id
when matched then
DELETE
"""
# add rows with ID = 1,2,3,4,5:
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 5;
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 = 5' )
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 echo on;
SET KEEP_TRAN_PARAMS ON;
set transaction read committed read consistency;
set list off;
set wng off;
set count on;
-- MUST HANG:
{SQL_TO_BE_RESTARTED};
-- check results:
-- ###############
select id 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 = 'del';
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 = 3 -- 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=3', SQL_TAG_THAT_WE_WAITING_FOR)
#########################
### L O C K E R - 2 ###
#########################
# Insert ID value that is less than previous min(id).
# Session-worker is executing its statement using PLAN ORDER,
# and it should see this new value and restart its statement:
con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(-1)' )
con_lock_2.commit()
con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = -1' )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # releases record with ID = 5 ==> now it can be locked by worker.
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = 5.
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=5', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = 5 for sure is locked by WORKER.
con_lock_1.execute_immediate( f'insert into {target_obj}(id) values(-2)' )
con_lock_1.commit()
con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = -2' )
#########################
### L O C K E R - 2 ###
#########################
# Insert ID value that is less than previous min(id).
# Session-worker is executing its statement using PLAN ORDER,
# and it should see this new value and restart its statement:
con_lock_2.commit() # releases record with ID = -1 ==> now it can be locked by worker.
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = -1.
#
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)
# If we come here then it means that record with ID = -1 for sure is locked by WORKER.
con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(-3)' )
con_lock_2.commit()
con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = -3' )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # releases record with ID = -2 ==> now it can be locked by worker.
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = -2.
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=-2', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = -2 for sure is locked by WORKER.
con_lock_2.commit()
# 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: 6
checked_mode: {checked_mode}, STDLOG: ID
checked_mode: {checked_mode}, STDLOG: =======
checked_mode: {checked_mode}, STDLOG: 1
checked_mode: {checked_mode}, STDLOG: 2
checked_mode: {checked_mode}, STDLOG: Records affected: 2
checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, STDLOG: 3 DEL 1
checked_mode: {checked_mode}, STDLOG: 4 DEL 1
checked_mode: {checked_mode}, STDLOG: -3 DEL 2
checked_mode: {checked_mode}, STDLOG: -2 DEL 2
checked_mode: {checked_mode}, STDLOG: -1 DEL 2
checked_mode: {checked_mode}, STDLOG: 3 DEL 2
checked_mode: {checked_mode}, STDLOG: 4 DEL 2
checked_mode: {checked_mode}, STDLOG: 5 DEL 2
checked_mode: {checked_mode}, STDLOG: Records affected: 8
"""
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: 6
E checked_mode: table, STDLOG: ID
E checked_mode: table, STDLOG:
E checked_mode: table, STDLOG: 1
E checked_mode: table, STDLOG: 2
E checked_mode: table, STDLOG: Records affected: 2
E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
E checked_mode: table, STDLOG:
E - checked_mode: table, STDLOG: 3 DEL 1
E + checked_mode: table, STDLOG: 3DEL 1
E - checked_mode: table, STDLOG: 4 DEL 1
E + checked_mode: table, STDLOG: 4DEL 1
E - checked_mode: table, STDLOG: -3 DEL 2
E + checked_mode: table, STDLOG: -3DEL 2
E - checked_mode: table, STDLOG: -2 DEL 2
E + checked_mode: table, STDLOG: -2DEL 2
E - checked_mode: table, STDLOG: -1 DEL 2
E + checked_mode: table, STDLOG: -1DEL 2
E - checked_mode: table, STDLOG: 3 DEL 2
E + checked_mode: table, STDLOG: 3DEL 2
E - checked_mode: table, STDLOG: 4 DEL 2
E + checked_mode: table, STDLOG: 4DEL 2
E - checked_mode: table, STDLOG: 5 DEL 2
E + checked_mode: table, STDLOG: 5DEL 2
E checked_mode: table, STDLOG: Records affected: 8
tests/functional/transactions/test_read_consist_sttm_restart_on_merge_02.py:486: AssertionError
|