2 @message |
assert
checked_mode: table, STDLOG: Records affected: 3
checked_mode: table, STDLOG: ID
checked_mode: table, STDLOG:
checked_mode: table, STDLOG: 3
checked_mode: table, STDLOG: 4
checked_mode: table, STDLOG: 5
checked_mode: table, STDLOG: 6
checked_mode: table, STDLOG: 7
checked_mode: table, STDLOG: 8
checked_mode: table, STDLOG: Records affected: 6
checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: table, STDLOG:
- checked_mode: table, STDLOG: 1 DEL 1
+ checked_mode: table, STDLOG: 1DEL 1
- checked_mode: table, STDLOG: 2 DEL 1
+ checked_mode: table, STDLOG: 2DEL 1
- 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: -1 DEL 2
+ checked_mode: table, STDLOG: -1DEL 2
- checked_mode: table, STDLOG: 1 DEL 2
+ checked_mode: table, STDLOG: 1DEL 2
- checked_mode: table, STDLOG: 2 DEL 2
+ checked_mode: table, STDLOG: 2DEL 2
checked_mode: table, STDLOG: Records affected: 7
LOG DETAILS:
2025-07-01 06:04:51.107
2025-07-01 06:04:51.112 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-01 06:04:51.118 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12476/tmp_worker.sql')
2025-07-01 06:04:51.124 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12476/tmp_worker.log')
2025-07-01 06:04:51.130 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12476/tmp_worker.err')
2025-07-01 06:04:51.136 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-01 06:04:51.143
2025-07-01 06:04:51.149 @pytest.mark.trace
2025-07-01 06:04:51.154 @pytest.mark.version('>=4.0.2')
2025-07-01 06:04:51.160 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-01 06:04:51.166 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-01 06:04:51.172
2025-07-01 06:04:51.178 for checked_mode in('table', 'view'):
2025-07-01 06:04:51.183 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-01 06:04:51.190 SQL_TO_BE_RESTARTED = f'delete /* {SQL_TAG_THAT_WE_WAITING_FOR} */ from {target_obj} order by id rows ( iif(exists(select 1 from {target_obj} where id < 0), 3, 8 ) )'
2025-07-01 06:04:51.202
2025-07-01 06:04:51.212 # add rows with ID = 1,2,3,4,5:
2025-07-01 06:04:51.219 sql_addi = f'''
2025-07-01 06:04:51.227 set term ^;
2025-07-01 06:04:51.234 execute block as
2025-07-01 06:04:51.245 begin
2025-07-01 06:04:51.253 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-01 06:04:51.260 end
2025-07-01 06:04:51.266 ^
2025-07-01 06:04:51.276 set term ;^
2025-07-01 06:04:51.286 insert into {target_obj}(id, x)
2025-07-01 06:04:51.295 select row_number()over(),row_number()over()
2025-07-01 06:04:51.304 from rdb$types rows 5;
2025-07-01 06:04:51.315 commit;
2025-07-01 06:04:51.324 '''
2025-07-01 06:04:51.332
2025-07-01 06:04:51.339 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-07-01 06:04:51.349 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-01 06:04:51.359 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-01 06:04:51.368 assert act.stderr == ''
2025-07-01 06:04:51.374 act.reset()
2025-07-01 06:04:51.385
2025-07-01 06:04:51.395
2025-07-01 06:04:51.402 trace_cfg_items = [
2025-07-01 06:04:51.409 'time_threshold = 0',
2025-07-01 06:04:51.414 'log_errors = true',
2025-07-01 06:04:51.420 'log_statement_start = true',
2025-07-01 06:04:51.427 'log_statement_finish = true',
2025-07-01 06:04:51.433 ]
2025-07-01 06:04:51.439
2025-07-01 06:04:51.445 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-01 06:04:51.453
2025-07-01 06:04:51.465 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:51.476
2025-07-01 06:04:51.487 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-01 06:04:51.496 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-01 06:04:51.503 cur_monitoring = tx_monitoring.cursor()
2025-07-01 06:04:51.511
2025-07-01 06:04:51.521 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-01 06:04:51.529 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-01 06:04:51.537 c.execute_immediate(sttm)
2025-07-01 06:04:51.542
2025-07-01 06:04:51.549 #########################
2025-07-01 06:04:51.555 ### L O C K E R - 1 ###
2025-07-01 06:04:51.561 #########################
2025-07-01 06:04:51.568 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = 5' )
2025-07-01 06:04:51.573
2025-07-01 06:04:51.579 worker_sql = f'''
2025-07-01 06:04:51.586 set list on;
2025-07-01 06:04:51.597 set autoddl off;
2025-07-01 06:04:51.606 set term ^;
2025-07-01 06:04:51.617 execute block returns (whoami varchar(30)) as
2025-07-01 06:04:51.629 begin
2025-07-01 06:04:51.640 whoami = 'WORKER'; -- , ATT#' || current_connection;
2025-07-01 06:04:51.649 rdb$set_context('USER_SESSION','WHO', whoami);
2025-07-01 06:04:51.655 -- suspend;
2025-07-01 06:04:51.662 end
2025-07-01 06:04:51.672 ^
2025-07-01 06:04:51.681 set term ;^
2025-07-01 06:04:51.689 commit;
2025-07-01 06:04:51.695 --set echo on;
2025-07-01 06:04:51.700 SET KEEP_TRAN_PARAMS ON;
2025-07-01 06:04:51.705 set transaction read committed read consistency;
2025-07-01 06:04:51.710 --select current_connection, current_transaction from rdb$database;
2025-07-01 06:04:51.715 set list off;
2025-07-01 06:04:51.720 set wng off;
2025-07-01 06:04:51.730 --set plan on;
2025-07-01 06:04:51.740 set count on;
2025-07-01 06:04:51.750
2025-07-01 06:04:51.759 -- delete from {target_obj} order by id rows ( iif(exists(select 1 from {target_obj} where id < 0), 3, 8 ) ); -- THIS MUST BE LOCKED
2025-07-01 06:04:51.767 {SQL_TO_BE_RESTARTED};
2025-07-01 06:04:51.777
2025-07-01 06:04:51.787 -- check results:
2025-07-01 06:04:51.796 -- ###############
2025-07-01 06:04:51.808
2025-07-01 06:04:51.817 select id from {target_obj} order by id; -- this will produce output only after all lockers do their commit/rollback
2025-07-01 06:04:51.824
2025-07-01 06:04:51.832 select v.old_id, v.op, v.snap_no_rank
2025-07-01 06:04:51.839 from v_worker_log v
2025-07-01 06:04:51.845 where v.op = 'del';
2025-07-01 06:04:51.851
2025-07-01 06:04:51.862 set width who 10;
2025-07-01 06:04:51.869 -- DO NOT check this! Values can differ here from one run to another!
2025-07-01 06:04:51.879 --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:51.890
2025-07-01 06:04:51.901 rollback;
2025-07-01 06:04:51.908
2025-07-01 06:04:51.915 '''
2025-07-01 06:04:51.926 fn_worker_sql.write_text(worker_sql)
2025-07-01 06:04:51.937
2025-07-01 06:04:51.947 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-01 06:04:51.956
2025-07-01 06:04:51.965 ############################################################################
2025-07-01 06:04:51.972 ### 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:51.979 ############################################################################
2025-07-01 06:04:51.985 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-01 06:04:51.997 '-user', act.db.user,
2025-07-01 06:04:52.009 '-password', act.db.password,
2025-07-01 06:04:52.017 act.db.dsn
2025-07-01 06:04:52.024 ],
2025-07-01 06:04:52.029 stdout = hang_out,
2025-07-01 06:04:52.034 stderr = hang_err
2025-07-01 06:04:52.039 )
2025-07-01 06:04:52.045
2025-07-01 06:04:52.050 # 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:52.056 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:04:52.065 #
2025-07-01 06:04:52.077 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:52.086
2025-07-01 06:04:52.093
2025-07-01 06:04:52.105 #########################
2025-07-01 06:04:52.112 ### L O C K E R - 2 ###
2025-07-01 06:04:52.122 #########################
2025-07-01 06:04:52.131 con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(6)' )
2025-07-01 06:04:52.142 con_lock_2.commit()
2025-07-01 06:04:52.152 con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = 6' )
2025-07-01 06:04:52.159
2025-07-01 06:04:52.167 #########################
2025-07-01 06:04:52.178 ### L O C K E R - 1 ###
2025-07-01 06:04:52.190 #########################
2025-07-01 06:04:52.201 con_lock_1.commit() # releases record with ID = 5 ==> now it can be locked by worker.
2025-07-01 06:04:52.211
2025-07-01 06:04:52.223 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 5.
2025-07-01 06:04:52.232 #
2025-07-01 06:04:52.245 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-01 06:04:52.256 # If we come here then it means that record with ID = 5 for sure is locked by WORKER.
2025-07-01 06:04:52.266
2025-07-01 06:04:52.277
2025-07-01 06:04:52.287 con_lock_1.execute_immediate( f'insert into {target_obj}(id) values(7)' )
2025-07-01 06:04:52.295 con_lock_1.commit()
2025-07-01 06:04:52.303 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = 7' )
2025-07-01 06:04:52.311
2025-07-01 06:04:52.321
2025-07-01 06:04:52.331 #########################
2025-07-01 06:04:52.339 ### L O C K E R - 2 ###
2025-07-01 06:04:52.350 #########################
2025-07-01 06:04:52.360 con_lock_2.commit() # releases record with ID = 6 ==> now it can be locked by worker.
2025-07-01 06:04:52.368
2025-07-01 06:04:52.375 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 6:
2025-07-01 06:04:52.381 #
2025-07-01 06:04:52.387 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 6', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:04:52.394 # If we come here then it means that record with ID = 6 for sure is locked by WORKER.
2025-07-01 06:04:52.400
2025-07-01 06:04:52.407
2025-07-01 06:04:52.413 con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(8)' )
2025-07-01 06:04:52.419 con_lock_2.commit()
2025-07-01 06:04:52.429 con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = 8' )
2025-07-01 06:04:52.437
2025-07-01 06:04:52.444 #########################
2025-07-01 06:04:52.450 ### L O C K E R - 1 ###
2025-07-01 06:04:52.455 #########################
2025-07-01 06:04:52.460 con_lock_1.commit() # releases record with ID = 7 ==> now it can be locked by worker.
2025-07-01 06:04:52.467
2025-07-01 06:04:52.474 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 7:
2025-07-01 06:04:52.483 #
2025-07-01 06:04:52.495 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 7', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:04:52.504 # If we come here then it means that record with ID = 7 for sure is locked by WORKER.
2025-07-01 06:04:52.510
2025-07-01 06:04:52.516 con_lock_1.execute_immediate( f'insert into {target_obj}(id) values(-1)' )
2025-07-01 06:04:52.522 con_lock_1.commit()
2025-07-01 06:04:52.531
2025-07-01 06:04:52.537 con_lock_2.commit() # WORKER will complete his job after this
2025-07-01 06:04:52.544
2025-07-01 06:04:52.551 # Here we wait for ISQL complete its mission:
2025-07-01 06:04:52.558 p_worker.wait()
2025-07-01 06:04:52.565
2025-07-01 06:04:52.571 #< with act.db.connect()
2025-07-01 06:04:52.579
2025-07-01 06:04:52.592 for g in (fn_worker_log, fn_worker_err):
2025-07-01 06:04:52.601 with g.open() as f:
2025-07-01 06:04:52.608 for line in f:
2025-07-01 06:04:52.615 if line.split():
2025-07-01 06:04:52.621 if g == fn_worker_log:
2025-07-01 06:04:52.627 print(f'checked_mode: {checked_mode}, STDLOG: {line}')
2025-07-01 06:04:52.633 else:
2025-07-01 06:04:52.639 print(f'UNEXPECTED STDERR {line}')
2025-07-01 06:04:52.647
2025-07-01 06:04:52.658 expected_stdout_worker = f"""
2025-07-01 06:04:52.668 checked_mode: {checked_mode}, STDLOG: Records affected: 3
2025-07-01 06:04:52.676 checked_mode: {checked_mode}, STDLOG: ID
2025-07-01 06:04:52.684 checked_mode: {checked_mode}, STDLOG: =======
2025-07-01 06:04:52.692 checked_mode: {checked_mode}, STDLOG: 3
2025-07-01 06:04:52.699 checked_mode: {checked_mode}, STDLOG: 4
2025-07-01 06:04:52.705 checked_mode: {checked_mode}, STDLOG: 5
2025-07-01 06:04:52.711 checked_mode: {checked_mode}, STDLOG: 6
2025-07-01 06:04:52.719 checked_mode: {checked_mode}, STDLOG: 7
2025-07-01 06:04:52.731 checked_mode: {checked_mode}, STDLOG: 8
2025-07-01 06:04:52.744 checked_mode: {checked_mode}, STDLOG: Records affected: 6
2025-07-01 06:04:52.756 checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:04:52.767 checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
2025-07-01 06:04:52.776 checked_mode: {checked_mode}, STDLOG: 1 DEL 1
2025-07-01 06:04:52.784 checked_mode: {checked_mode}, STDLOG: 2 DEL 1
2025-07-01 06:04:52.797 checked_mode: {checked_mode}, STDLOG: 3 DEL 1
2025-07-01 06:04:52.807 checked_mode: {checked_mode}, STDLOG: 4 DEL 1
2025-07-01 06:04:52.817 checked_mode: {checked_mode}, STDLOG: -1 DEL 2
2025-07-01 06:04:52.825 checked_mode: {checked_mode}, STDLOG: 1 DEL 2
2025-07-01 06:04:52.831 checked_mode: {checked_mode}, STDLOG: 2 DEL 2
2025-07-01 06:04:52.838 checked_mode: {checked_mode}, STDLOG: Records affected: 7
2025-07-01 06:04:52.843 """
2025-07-01 06:04:52.848
2025-07-01 06:04:52.853 act.expected_stdout = expected_stdout_worker
2025-07-01 06:04:52.858 act.stdout = capsys.readouterr().out
2025-07-01 06:04:52.864 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-01 06:04:52.871 E assert
2025-07-01 06:04:52.880 E checked_mode: table, STDLOG: Records affected: 3
2025-07-01 06:04:52.889 E checked_mode: table, STDLOG: ID
2025-07-01 06:04:52.898 E checked_mode: table, STDLOG:
2025-07-01 06:04:52.909 E checked_mode: table, STDLOG: 3
2025-07-01 06:04:52.922 E checked_mode: table, STDLOG: 4
2025-07-01 06:04:52.932 E checked_mode: table, STDLOG: 5
2025-07-01 06:04:52.939 E checked_mode: table, STDLOG: 6
2025-07-01 06:04:52.945 E checked_mode: table, STDLOG: 7
2025-07-01 06:04:52.950 E checked_mode: table, STDLOG: 8
2025-07-01 06:04:52.954 E checked_mode: table, STDLOG: Records affected: 6
2025-07-01 06:04:52.959 E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:04:52.964 E checked_mode: table, STDLOG:
2025-07-01 06:04:52.970 E - checked_mode: table, STDLOG: 1 DEL 1
2025-07-01 06:04:52.982 E + checked_mode: table, STDLOG: 1DEL 1
2025-07-01 06:04:52.989 E - checked_mode: table, STDLOG: 2 DEL 1
2025-07-01 06:04:53.000 E + checked_mode: table, STDLOG: 2DEL 1
2025-07-01 06:04:53.006 E - checked_mode: table, STDLOG: 3 DEL 1
2025-07-01 06:04:53.018 E + checked_mode: table, STDLOG: 3DEL 1
2025-07-01 06:04:53.023 E - checked_mode: table, STDLOG: 4 DEL 1
2025-07-01 06:04:53.035 E + checked_mode: table, STDLOG: 4DEL 1
2025-07-01 06:04:53.039 E - checked_mode: table, STDLOG: -1 DEL 2
2025-07-01 06:04:53.049 E + checked_mode: table, STDLOG: -1DEL 2
2025-07-01 06:04:53.054 E - checked_mode: table, STDLOG: 1 DEL 2
2025-07-01 06:04:53.064 E + checked_mode: table, STDLOG: 1DEL 2
2025-07-01 06:04:53.070 E - checked_mode: table, STDLOG: 2 DEL 2
2025-07-01 06:04:53.088 E + checked_mode: table, STDLOG: 2DEL 2
2025-07-01 06:04:53.100 E checked_mode: table, STDLOG: Records affected: 7
2025-07-01 06:04:53.108
2025-07-01 06:04:53.115 tests/functional/transactions/test_read_consist_sttm_restart_on_delete_01.py:447: AssertionError
2025-07-01 06:04:53.123 ---------------------------- Captured stdout setup -----------------------------
2025-07-01 06:04:53.134 Creating db: localhost:/var/tmp/qa_2024/test_12476/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_12476/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12476/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12476/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'delete /* {SQL_TAG_THAT_WE_WAITING_FOR} */ from {target_obj} order by id rows ( iif(exists(select 1 from {target_obj} where id < 0), 3, 8 ) )'
# 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;
--select current_connection, current_transaction from rdb$database;
set list off;
set wng off;
--set plan on;
set count on;
-- delete from {target_obj} order by id rows ( iif(exists(select 1 from {target_obj} where id < 0), 3, 8 ) ); -- THIS MUST BE LOCKED
{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,
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) values(6)' )
con_lock_2.commit()
con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = 6' )
#########################
### 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(7)' )
con_lock_1.commit()
con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = 7' )
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.commit() # releases record with ID = 6 ==> now it can be locked by worker.
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = 6:
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 6', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = 6 for sure is locked by WORKER.
con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(8)' )
con_lock_2.commit()
con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = 8' )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # releases record with ID = 7 ==> now it can be locked by worker.
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = 7:
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 7', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = 7 for sure is locked by WORKER.
con_lock_1.execute_immediate( f'insert into {target_obj}(id) values(-1)' )
con_lock_1.commit()
con_lock_2.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: 3
checked_mode: {checked_mode}, STDLOG: ID
checked_mode: {checked_mode}, STDLOG: =======
checked_mode: {checked_mode}, STDLOG: 3
checked_mode: {checked_mode}, STDLOG: 4
checked_mode: {checked_mode}, STDLOG: 5
checked_mode: {checked_mode}, STDLOG: 6
checked_mode: {checked_mode}, STDLOG: 7
checked_mode: {checked_mode}, STDLOG: 8
checked_mode: {checked_mode}, STDLOG: Records affected: 6
checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, STDLOG: 1 DEL 1
checked_mode: {checked_mode}, STDLOG: 2 DEL 1
checked_mode: {checked_mode}, STDLOG: 3 DEL 1
checked_mode: {checked_mode}, STDLOG: 4 DEL 1
checked_mode: {checked_mode}, STDLOG: -1 DEL 2
checked_mode: {checked_mode}, STDLOG: 1 DEL 2
checked_mode: {checked_mode}, STDLOG: 2 DEL 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: 3
E checked_mode: table, STDLOG: ID
E checked_mode: table, STDLOG:
E checked_mode: table, STDLOG: 3
E checked_mode: table, STDLOG: 4
E checked_mode: table, STDLOG: 5
E checked_mode: table, STDLOG: 6
E checked_mode: table, STDLOG: 7
E checked_mode: table, STDLOG: 8
E checked_mode: table, STDLOG: Records affected: 6
E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
E checked_mode: table, STDLOG:
E - checked_mode: table, STDLOG: 1 DEL 1
E + checked_mode: table, STDLOG: 1DEL 1
E - checked_mode: table, STDLOG: 2 DEL 1
E + checked_mode: table, STDLOG: 2DEL 1
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: -1 DEL 2
E + checked_mode: table, STDLOG: -1DEL 2
E - checked_mode: table, STDLOG: 1 DEL 2
E + checked_mode: table, STDLOG: 1DEL 2
E - checked_mode: table, STDLOG: 2 DEL 2
E + checked_mode: table, STDLOG: 2DEL 2
E checked_mode: table, STDLOG: Records affected: 7
tests/functional/transactions/test_read_consist_sttm_restart_on_delete_01.py:447: AssertionError
|