2 @message |
assert
checked_mode: table, STDLOG: Records affected: 4
checked_mode: table, STDLOG: ID
checked_mode: table, STDLOG:
checked_mode: table, STDLOG: -5
checked_mode: table, STDLOG: -2
checked_mode: table, STDLOG: -1
checked_mode: table, STDLOG: 3
checked_mode: table, STDLOG: 4
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: 2 UPD 1
+ checked_mode: table, STDLOG: 2UPD 1
- checked_mode: table, STDLOG: 2 UPD 2
+ checked_mode: table, STDLOG: 2UPD 2
- checked_mode: table, STDLOG: 1 UPD 2
+ checked_mode: table, STDLOG: 1UPD 2
- checked_mode: table, STDLOG: 2 UPD 3
+ checked_mode: table, STDLOG: 2UPD 3
- checked_mode: table, STDLOG: 1 UPD 3
+ checked_mode: table, STDLOG: 1UPD 3
- checked_mode: table, STDLOG: 2 UPD 4
+ checked_mode: table, STDLOG: 2UPD 4
- checked_mode: table, STDLOG: 1 UPD 4
+ checked_mode: table, STDLOG: 1UPD 4
- checked_mode: table, STDLOG: -3 UPD 4
+ checked_mode: table, STDLOG: -3UPD 4
- checked_mode: table, STDLOG: -4 UPD 4
+ checked_mode: table, STDLOG: -4UPD 4
checked_mode: table, STDLOG: Records affected: 9
LOG DETAILS:
2025-07-02 06:08:00.530
2025-07-02 06:08:00.537 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-02 06:08:00.543 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12488/tmp_worker.sql')
2025-07-02 06:08:00.550 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12488/tmp_worker.log')
2025-07-02 06:08:00.556 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12488/tmp_worker.err')
2025-07-02 06:08:00.562 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-02 06:08:00.568
2025-07-02 06:08:00.574 @pytest.mark.trace
2025-07-02 06:08:00.585 @pytest.mark.version('>=4.0')
2025-07-02 06:08:00.595 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-02 06:08:00.607 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-02 06:08:00.619
2025-07-02 06:08:00.632 for checked_mode in('table', 'view'):
2025-07-02 06:08:00.643 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-02 06:08:00.652
2025-07-02 06:08:00.658 SQL_TO_BE_RESTARTED = f"update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = -id where id <= 2 order by id DESC rows 4"
2025-07-02 06:08:00.664
2025-07-02 06:08:00.674 sql_addi = f'''
2025-07-02 06:08:00.684 set term ^;
2025-07-02 06:08:00.696 execute block as
2025-07-02 06:08:00.704 begin
2025-07-02 06:08:00.712 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-02 06:08:00.719 end
2025-07-02 06:08:00.732 ^
2025-07-02 06:08:00.744 set term ;^
2025-07-02 06:08:00.752 insert into {target_obj}(id, x)
2025-07-02 06:08:00.759 select row_number()over(),row_number()over()
2025-07-02 06:08:00.766 from rdb$types rows 5;
2025-07-02 06:08:00.772 commit;
2025-07-02 06:08:00.778 '''
2025-07-02 06:08:00.784
2025-07-02 06:08:00.791 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ))
2025-07-02 06:08:00.797 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-02 06:08:00.803 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-02 06:08:00.810 assert act.stderr == ''
2025-07-02 06:08:00.815 act.reset()
2025-07-02 06:08:00.823
2025-07-02 06:08:00.834 trace_cfg_items = [
2025-07-02 06:08:00.845 'time_threshold = 0',
2025-07-02 06:08:00.853 'log_errors = true',
2025-07-02 06:08:00.860 'log_statement_start = true',
2025-07-02 06:08:00.867 'log_statement_finish = true',
2025-07-02 06:08:00.876 ]
2025-07-02 06:08:00.885
2025-07-02 06:08:00.892 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-02 06:08:00.906
2025-07-02 06:08:00.916 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:08:00.925
2025-07-02 06:08:00.933 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-02 06:08:00.938 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-02 06:08:00.944 cur_monitoring = tx_monitoring.cursor()
2025-07-02 06:08:00.950
2025-07-02 06:08:00.955 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-02 06:08:00.961 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-02 06:08:00.966 c.execute_immediate(sttm)
2025-07-02 06:08:00.971
2025-07-02 06:08:00.976
2025-07-02 06:08:00.982 #########################
2025-07-02 06:08:00.987 ### L O C K E R - 1 ###
2025-07-02 06:08:00.993 #########################
2025-07-02 06:08:00.999
2025-07-02 06:08:01.011 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id=1' )
2025-07-02 06:08:01.023
2025-07-02 06:08:01.035 worker_sql = f'''
2025-07-02 06:08:01.044 set list on;
2025-07-02 06:08:01.052 set autoddl off;
2025-07-02 06:08:01.059 set term ^;
2025-07-02 06:08:01.066 execute block returns (whoami varchar(30)) as
2025-07-02 06:08:01.073 begin
2025-07-02 06:08:01.080 whoami = 'WORKER'; -- , ATT#' || current_connection;
2025-07-02 06:08:01.092 rdb$set_context('USER_SESSION','WHO', whoami);
2025-07-02 06:08:01.104 -- suspend;
2025-07-02 06:08:01.113 end
2025-07-02 06:08:01.120 ^
2025-07-02 06:08:01.127 set term ;^
2025-07-02 06:08:01.133 commit;
2025-07-02 06:08:01.139 SET KEEP_TRAN_PARAMS ON;
2025-07-02 06:08:01.145 set transaction read committed read consistency;
2025-07-02 06:08:01.153 --select current_connection, current_transaction from rdb$database;
2025-07-02 06:08:01.165 set list off;
2025-07-02 06:08:01.180 set wng off;
2025-07-02 06:08:01.194
2025-07-02 06:08:01.205 --set plan on;
2025-07-02 06:08:01.214 set count on;
2025-07-02 06:08:01.225
2025-07-02 06:08:01.234 -- this must hang because of locker-1:
2025-07-02 06:08:01.242 {SQL_TO_BE_RESTARTED};
2025-07-02 06:08:01.255
2025-07-02 06:08:01.265 -- check results:
2025-07-02 06:08:01.275 -- ###############
2025-07-02 06:08:01.285 select id from {target_obj} order by id; -- one record must remain, with ID = -5
2025-07-02 06:08:01.295
2025-07-02 06:08:01.308 select v.old_id, v.op, v.snap_no_rank -- snap_no_rank must have four unique values: 1,2,3 and 4.
2025-07-02 06:08:01.319 from v_worker_log v
2025-07-02 06:08:01.328 where v.op = 'upd';
2025-07-02 06:08:01.335
2025-07-02 06:08:01.343 --set width who 10;
2025-07-02 06:08:01.353 -- DO NOT check this! Values can differ here from one run to another!
2025-07-02 06:08:01.361 -- 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:08:01.373 rollback;
2025-07-02 06:08:01.384
2025-07-02 06:08:01.394 '''
2025-07-02 06:08:01.402
2025-07-02 06:08:01.410 fn_worker_sql.write_text(worker_sql)
2025-07-02 06:08:01.421
2025-07-02 06:08:01.431 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-02 06:08:01.439
2025-07-02 06:08:01.448 ############################################################################
2025-07-02 06:08:01.462 ### 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:08:01.475 ############################################################################
2025-07-02 06:08:01.484 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-02 06:08:01.490 '-user', act.db.user,
2025-07-02 06:08:01.496 '-password', act.db.password,
2025-07-02 06:08:01.502 '-pag', '999999',
2025-07-02 06:08:01.507 act.db.dsn
2025-07-02 06:08:01.513 ],
2025-07-02 06:08:01.518 stdout = hang_out,
2025-07-02 06:08:01.523 stderr = hang_err
2025-07-02 06:08:01.528 )
2025-07-02 06:08:01.533
2025-07-02 06:08:01.539 # NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- see above SQL_TO_BE_RESTARTED
2025-07-02 06:08:01.546 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-02 06:08:01.558 #
2025-07-02 06:08:01.569 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:08:01.577
2025-07-02 06:08:01.583 #########################
2025-07-02 06:08:01.593 ### L O C K E R - 2 ###
2025-07-02 06:08:01.600 #########################
2025-07-02 06:08:01.606
2025-07-02 06:08:01.615 # Change ID so that it **will* be included in the set of rows that must be affected by session-worker:
2025-07-02 06:08:01.627 con_lock_2.execute_immediate( f'update {target_obj} set id = -5 where abs(id) = 5;' )
2025-07-02 06:08:01.635 con_lock_2.commit()
2025-07-02 06:08:01.642 con_lock_2.execute_immediate( f'update {target_obj} set id = id where abs(id) = 5;' )
2025-07-02 06:08:01.648
2025-07-02 06:08:01.654 #########################
2025-07-02 06:08:01.661 ### L O C K E R - 1 ###
2025-07-02 06:08:01.668 #########################
2025-07-02 06:08:01.683
2025-07-02 06:08:01.697 con_lock_1.commit() # releases record with ID=1 ==> now it can be locked by worker.
2025-07-02 06:08:01.706
2025-07-02 06:08:01.714 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 1.
2025-07-02 06:08:01.726 #
2025-07-02 06:08:01.737 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:08:01.749
2025-07-02 06:08:01.761 # If we come here then it means that record with ID = 1 for sure is locked by WORKER.
2025-07-02 06:08:01.774
2025-07-02 06:08:01.785 # Change ID so that it **will* be included in the set of rows that must be affected by session-worker:
2025-07-02 06:08:01.792 con_lock_1.execute_immediate( f'update {target_obj} set id = -4 where abs(id) = 4;' )
2025-07-02 06:08:01.798 con_lock_1.commit()
2025-07-02 06:08:01.805 con_lock_1.execute_immediate( f'update {target_obj} set id = id where abs(id) = 4;' )
2025-07-02 06:08:01.811
2025-07-02 06:08:01.817
2025-07-02 06:08:01.823 #########################
2025-07-02 06:08:01.830 ### L O C K E R - 2 ###
2025-07-02 06:08:01.838 #########################
2025-07-02 06:08:01.848
2025-07-02 06:08:01.857 con_lock_2.commit() # releases record with ID = -5, but session-worker is waiting for record with ID = -4 (that was changed by locker-1).
2025-07-02 06:08:01.864
2025-07-02 06:08:01.872 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = -5:
2025-07-02 06:08:01.879 #
2025-07-02 06:08:01.885 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:08:01.892
2025-07-02 06:08:01.900 # If we come here then it means that record with ID = -5 for sure is locked by WORKER.
2025-07-02 06:08:01.906
2025-07-02 06:08:01.913 con_lock_2.execute_immediate( f'update {target_obj} set id = -3 where abs(id) = 3;' )
2025-07-02 06:08:01.920 con_lock_2.commit()
2025-07-02 06:08:01.926 con_lock_2.execute_immediate( f'update {target_obj} set id = id where abs(id) = 3;' )
2025-07-02 06:08:01.935
2025-07-02 06:08:01.946 #########################
2025-07-02 06:08:01.953 ### L O C K E R - 1 ###
2025-07-02 06:08:01.961 #########################
2025-07-02 06:08:01.973
2025-07-02 06:08:01.983 con_lock_1.commit() # This releases row with ID=-4 but session-worker is waiting for ID = - 3 (changed by locker-2).
2025-07-02 06:08:01.990
2025-07-02 06:08:01.997 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = -4:
2025-07-02 06:08:02.004 #
2025-07-02 06:08:02.011 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = -4', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-02 06:08:02.018
2025-07-02 06:08:02.031 # If we come here then it means that record with ID = -4 for sure is locked by WORKER.
2025-07-02 06:08:02.040
2025-07-02 06:08:02.046 con_lock_2.commit() # This releases row with ID=-3. No more locked rows so session-worker can finish its mission.
2025-07-02 06:08:02.053
2025-07-02 06:08:02.064 # Here we wait for ISQL complete its mission:
2025-07-02 06:08:02.078 p_worker.wait()
2025-07-02 06:08:02.088
2025-07-02 06:08:02.096 #< with act.db.connect()
2025-07-02 06:08:02.103
2025-07-02 06:08:02.109 for g in (fn_worker_log, fn_worker_err):
2025-07-02 06:08:02.121 with g.open() as f:
2025-07-02 06:08:02.130 for line in f:
2025-07-02 06:08:02.137 if line.split():
2025-07-02 06:08:02.144 if g == fn_worker_log:
2025-07-02 06:08:02.151 print(f'checked_mode: {checked_mode}, STDLOG: {line}')
2025-07-02 06:08:02.159 else:
2025-07-02 06:08:02.167 print(f'UNEXPECTED STDERR {line}')
2025-07-02 06:08:02.174
2025-07-02 06:08:02.188 expected_stdout_worker = f"""
2025-07-02 06:08:02.197 checked_mode: {checked_mode}, STDLOG: Records affected: 4
2025-07-02 06:08:02.205
2025-07-02 06:08:02.213 checked_mode: {checked_mode}, STDLOG: ID
2025-07-02 06:08:02.220 checked_mode: {checked_mode}, STDLOG: =======
2025-07-02 06:08:02.228 checked_mode: {checked_mode}, STDLOG: -5
2025-07-02 06:08:02.236 checked_mode: {checked_mode}, STDLOG: -2
2025-07-02 06:08:02.244 checked_mode: {checked_mode}, STDLOG: -1
2025-07-02 06:08:02.251 checked_mode: {checked_mode}, STDLOG: 3
2025-07-02 06:08:02.259 checked_mode: {checked_mode}, STDLOG: 4
2025-07-02 06:08:02.267 checked_mode: {checked_mode}, STDLOG: Records affected: 5
2025-07-02 06:08:02.274
2025-07-02 06:08:02.286 checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-02 06:08:02.297 checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
2025-07-02 06:08:02.305 checked_mode: {checked_mode}, STDLOG: 2 UPD 1
2025-07-02 06:08:02.311 checked_mode: {checked_mode}, STDLOG: 2 UPD 2
2025-07-02 06:08:02.316 checked_mode: {checked_mode}, STDLOG: 1 UPD 2
2025-07-02 06:08:02.322 checked_mode: {checked_mode}, STDLOG: 2 UPD 3
2025-07-02 06:08:02.328 checked_mode: {checked_mode}, STDLOG: 1 UPD 3
2025-07-02 06:08:02.334 checked_mode: {checked_mode}, STDLOG: 2 UPD 4
2025-07-02 06:08:02.340 checked_mode: {checked_mode}, STDLOG: 1 UPD 4
2025-07-02 06:08:02.345 checked_mode: {checked_mode}, STDLOG: -3 UPD 4
2025-07-02 06:08:02.350 checked_mode: {checked_mode}, STDLOG: -4 UPD 4
2025-07-02 06:08:02.355 checked_mode: {checked_mode}, STDLOG: Records affected: 9
2025-07-02 06:08:02.360 """
2025-07-02 06:08:02.366 act.expected_stdout = expected_stdout_worker
2025-07-02 06:08:02.373 act.stdout = capsys.readouterr().out
2025-07-02 06:08:02.380 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-02 06:08:02.387 E assert
2025-07-02 06:08:02.395 E checked_mode: table, STDLOG: Records affected: 4
2025-07-02 06:08:02.404 E checked_mode: table, STDLOG: ID
2025-07-02 06:08:02.412 E checked_mode: table, STDLOG:
2025-07-02 06:08:02.420 E checked_mode: table, STDLOG: -5
2025-07-02 06:08:02.428 E checked_mode: table, STDLOG: -2
2025-07-02 06:08:02.436 E checked_mode: table, STDLOG: -1
2025-07-02 06:08:02.444 E checked_mode: table, STDLOG: 3
2025-07-02 06:08:02.452 E checked_mode: table, STDLOG: 4
2025-07-02 06:08:02.460 E checked_mode: table, STDLOG: Records affected: 5
2025-07-02 06:08:02.468 E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-02 06:08:02.476 E checked_mode: table, STDLOG:
2025-07-02 06:08:02.488 E - checked_mode: table, STDLOG: 2 UPD 1
2025-07-02 06:08:02.509 E + checked_mode: table, STDLOG: 2UPD 1
2025-07-02 06:08:02.516 E - checked_mode: table, STDLOG: 2 UPD 2
2025-07-02 06:08:02.528 E + checked_mode: table, STDLOG: 2UPD 2
2025-07-02 06:08:02.536 E - checked_mode: table, STDLOG: 1 UPD 2
2025-07-02 06:08:02.555 E + checked_mode: table, STDLOG: 1UPD 2
2025-07-02 06:08:02.563 E - checked_mode: table, STDLOG: 2 UPD 3
2025-07-02 06:08:02.579 E + checked_mode: table, STDLOG: 2UPD 3
2025-07-02 06:08:02.589 E - checked_mode: table, STDLOG: 1 UPD 3
2025-07-02 06:08:02.604 E + checked_mode: table, STDLOG: 1UPD 3
2025-07-02 06:08:02.612 E - checked_mode: table, STDLOG: 2 UPD 4
2025-07-02 06:08:02.628 E + checked_mode: table, STDLOG: 2UPD 4
2025-07-02 06:08:02.636 E - checked_mode: table, STDLOG: 1 UPD 4
2025-07-02 06:08:02.653 E + checked_mode: table, STDLOG: 1UPD 4
2025-07-02 06:08:02.661 E - checked_mode: table, STDLOG: -3 UPD 4
2025-07-02 06:08:02.687 E + checked_mode: table, STDLOG: -3UPD 4
2025-07-02 06:08:02.696 E - checked_mode: table, STDLOG: -4 UPD 4
2025-07-02 06:08:02.711 E + checked_mode: table, STDLOG: -4UPD 4
2025-07-02 06:08:02.719 E checked_mode: table, STDLOG: Records affected: 9
2025-07-02 06:08:02.727
2025-07-02 06:08:02.739 tests/functional/transactions/test_read_consist_sttm_restart_on_update_04.py:442: AssertionError
2025-07-02 06:08:02.752 ---------------------------- Captured stdout setup -----------------------------
2025-07-02 06:08:02.761 Creating db: localhost:/var/tmp/qa_2024/test_12488/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_12488/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12488/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12488/tmp_worker.err')
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>
@pytest.mark.trace
@pytest.mark.version('>=4.0')
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"update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = -id where id <= 2 order by id DESC rows 4"
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=1' )
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;
--select current_connection, current_transaction from rdb$database;
set list off;
set wng off;
--set plan on;
set count on;
-- this must hang because of locker-1:
{SQL_TO_BE_RESTARTED};
-- check results:
-- ###############
select id from {target_obj} order by id; -- one record must remain, with ID = -5
select v.old_id, v.op, v.snap_no_rank -- snap_no_rank must have four unique values: 1,2,3 and 4.
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', '999999',
act.db.dsn
],
stdout = hang_out,
stderr = hang_err
)
# NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- 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=2', SQL_TAG_THAT_WE_WAITING_FOR)
#########################
### L O C K E R - 2 ###
#########################
# Change ID so that it **will* be included in the set of rows that must be affected by session-worker:
con_lock_2.execute_immediate( f'update {target_obj} set id = -5 where abs(id) = 5;' )
con_lock_2.commit()
con_lock_2.execute_immediate( f'update {target_obj} set id = id where abs(id) = 5;' )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.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.
# Change ID so that it **will* be included in the set of rows that must be affected by session-worker:
con_lock_1.execute_immediate( f'update {target_obj} set id = -4 where abs(id) = 4;' )
con_lock_1.commit()
con_lock_1.execute_immediate( f'update {target_obj} set id = id where abs(id) = 4;' )
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.commit() # releases record with ID = -5, but session-worker is waiting for record with ID = -4 (that was changed by locker-1).
# 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_2.execute_immediate( f'update {target_obj} set id = -3 where abs(id) = 3;' )
con_lock_2.commit()
con_lock_2.execute_immediate( f'update {target_obj} set id = id where abs(id) = 3;' )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # This releases row with ID=-4 but session-worker is waiting for ID = - 3 (changed by locker-2).
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = -4:
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = -4', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = -4 for sure is locked by WORKER.
con_lock_2.commit() # This releases row with ID=-3. No more locked rows so session-worker can finish its mission.
# 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: 4
checked_mode: {checked_mode}, STDLOG: ID
checked_mode: {checked_mode}, STDLOG: =======
checked_mode: {checked_mode}, STDLOG: -5
checked_mode: {checked_mode}, STDLOG: -2
checked_mode: {checked_mode}, STDLOG: -1
checked_mode: {checked_mode}, STDLOG: 3
checked_mode: {checked_mode}, STDLOG: 4
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: 2 UPD 1
checked_mode: {checked_mode}, STDLOG: 2 UPD 2
checked_mode: {checked_mode}, STDLOG: 1 UPD 2
checked_mode: {checked_mode}, STDLOG: 2 UPD 3
checked_mode: {checked_mode}, STDLOG: 1 UPD 3
checked_mode: {checked_mode}, STDLOG: 2 UPD 4
checked_mode: {checked_mode}, STDLOG: 1 UPD 4
checked_mode: {checked_mode}, STDLOG: -3 UPD 4
checked_mode: {checked_mode}, STDLOG: -4 UPD 4
checked_mode: {checked_mode}, STDLOG: Records affected: 9
"""
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: 4
E checked_mode: table, STDLOG: ID
E checked_mode: table, STDLOG:
E checked_mode: table, STDLOG: -5
E checked_mode: table, STDLOG: -2
E checked_mode: table, STDLOG: -1
E checked_mode: table, STDLOG: 3
E checked_mode: table, STDLOG: 4
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: 2 UPD 1
E + checked_mode: table, STDLOG: 2UPD 1
E - checked_mode: table, STDLOG: 2 UPD 2
E + checked_mode: table, STDLOG: 2UPD 2
E - checked_mode: table, STDLOG: 1 UPD 2
E + checked_mode: table, STDLOG: 1UPD 2
E - checked_mode: table, STDLOG: 2 UPD 3
E + checked_mode: table, STDLOG: 2UPD 3
E - checked_mode: table, STDLOG: 1 UPD 3
E + checked_mode: table, STDLOG: 1UPD 3
E - checked_mode: table, STDLOG: 2 UPD 4
E + checked_mode: table, STDLOG: 2UPD 4
E - checked_mode: table, STDLOG: 1 UPD 4
E + checked_mode: table, STDLOG: 1UPD 4
E - checked_mode: table, STDLOG: -3 UPD 4
E + checked_mode: table, STDLOG: -3UPD 4
E - checked_mode: table, STDLOG: -4 UPD 4
E + checked_mode: table, STDLOG: -4UPD 4
E checked_mode: table, STDLOG: Records affected: 9
tests/functional/transactions/test_read_consist_sttm_restart_on_update_04.py:442: AssertionError
|