2 @message |
assert
checked_mode: table, STDLOG: Records affected: 0
checked_mode: table, STDLOG: ID
checked_mode: table, STDLOG:
checked_mode: table, STDLOG: 1
checked_mode: table, STDLOG: 2
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: 9
checked_mode: table, STDLOG: 10
checked_mode: table, STDLOG: Records affected: 10
checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: table, STDLOG:
- checked_mode: table, STDLOG: 5 DEL 1
+ checked_mode: table, STDLOG: 5DEL 1
- checked_mode: table, STDLOG: 4 DEL 1
+ checked_mode: table, STDLOG: 4DEL 1
- checked_mode: table, STDLOG: 3 DEL 1
+ checked_mode: table, STDLOG: 3DEL 1
- checked_mode: table, STDLOG: 2 DEL 1
+ checked_mode: table, STDLOG: 2DEL 1
checked_mode: table, STDLOG: Records affected: 4
LOG DETAILS:
2025-07-01 06:04:40.230
2025-07-01 06:04:40.236 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-01 06:04:40.242 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12472/tmp_worker.sql')
2025-07-01 06:04:40.248 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12472/tmp_worker.log')
2025-07-01 06:04:40.254 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12472/tmp_worker.err')
2025-07-01 06:04:40.263 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-01 06:04:40.270
2025-07-01 06:04:40.276 @pytest.mark.trace
2025-07-01 06:04:40.283 @pytest.mark.version('>=4.0.3')
2025-07-01 06:04:40.290 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-01 06:04:40.303 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-01 06:04:40.309
2025-07-01 06:04:40.315 for checked_mode in('table', 'view'):
2025-07-01 06:04:40.322 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-01 06:04:40.328
2025-07-01 06:04:40.336 SQL_TO_BE_RESTARTED = f'delete /* {SQL_TAG_THAT_WE_WAITING_FOR} */ from {target_obj} where not exists(select * from {target_obj} where id >= 10) order by id desc'
2025-07-01 06:04:40.343
2025-07-01 06:04:40.349 # add rows with ID = 1,2,3,4,5:
2025-07-01 06:04:40.359 sql_addi='''
2025-07-01 06:04:40.366 set term ^;
2025-07-01 06:04:40.377 execute block as
2025-07-01 06:04:40.388 begin
2025-07-01 06:04:40.399 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-01 06:04:40.409 end
2025-07-01 06:04:40.417 ^
2025-07-01 06:04:40.423 set term ;^
2025-07-01 06:04:40.429 insert into test(id, x)
2025-07-01 06:04:40.436 select row_number()over(),row_number()over()
2025-07-01 06:04:40.442 from rdb$types rows 5;
2025-07-01 06:04:40.449 commit;
2025-07-01 06:04:40.456 '''
2025-07-01 06:04:40.463 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-07-01 06:04:40.470 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-01 06:04:40.477 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-01 06:04:40.484 assert act.stderr == ''
2025-07-01 06:04:40.490 act.reset()
2025-07-01 06:04:40.497
2025-07-01 06:04:40.509 trace_cfg_items = [
2025-07-01 06:04:40.521 'time_threshold = 0',
2025-07-01 06:04:40.530 'log_errors = true',
2025-07-01 06:04:40.537 'log_statement_start = true',
2025-07-01 06:04:40.543 'log_statement_finish = true',
2025-07-01 06:04:40.549 ]
2025-07-01 06:04:40.556
2025-07-01 06:04:40.563 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-01 06:04:40.569
2025-07-01 06:04:40.577 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:40.584
2025-07-01 06:04:40.595 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-01 06:04:40.600 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-01 06:04:40.605 cur_monitoring = tx_monitoring.cursor()
2025-07-01 06:04:40.610
2025-07-01 06:04:40.615 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-01 06:04:40.620 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-01 06:04:40.624 c.execute_immediate(sttm)
2025-07-01 06:04:40.629
2025-07-01 06:04:40.633 #########################
2025-07-01 06:04:40.638 ### L O C K E R - 1 ###
2025-07-01 06:04:40.643 #########################
2025-07-01 06:04:40.647 con_lock_1.execute_immediate( 'update test set id=id where id = 1' )
2025-07-01 06:04:40.653
2025-07-01 06:04:40.659 worker_sql = f'''
2025-07-01 06:04:40.669 set list on;
2025-07-01 06:04:40.679 set autoddl off;
2025-07-01 06:04:40.687 set term ^;
2025-07-01 06:04:40.694 execute block returns (whoami varchar(30)) as
2025-07-01 06:04:40.699 begin
2025-07-01 06:04:40.705 whoami = 'WORKER'; -- , ATT#' || current_connection;
2025-07-01 06:04:40.713 rdb$set_context('USER_SESSION','WHO', whoami);
2025-07-01 06:04:40.720 -- suspend;
2025-07-01 06:04:40.727 end
2025-07-01 06:04:40.732 ^
2025-07-01 06:04:40.738 set term ;^
2025-07-01 06:04:40.744 commit;
2025-07-01 06:04:40.750 SET KEEP_TRAN_PARAMS ON;
2025-07-01 06:04:40.758 set transaction read committed read consistency;
2025-07-01 06:04:40.766 set list off;
2025-07-01 06:04:40.773 set wng off;
2025-07-01 06:04:40.779 set count on;
2025-07-01 06:04:40.784
2025-07-01 06:04:40.790 -- this must hang because of locker-1:
2025-07-01 06:04:40.796 {SQL_TO_BE_RESTARTED};
2025-07-01 06:04:40.801
2025-07-01 06:04:40.808 -- check results:
2025-07-01 06:04:40.813 -- ###############
2025-07-01 06:04:40.819 select id from test order by id; -- this will produce output only after all lockers do their commit/rollback
2025-07-01 06:04:40.824
2025-07-01 06:04:40.830 select v.old_id, v.op, v.snap_no_rank
2025-07-01 06:04:40.838 from v_worker_log v
2025-07-01 06:04:40.848 where v.op = 'del';
2025-07-01 06:04:40.857
2025-07-01 06:04:40.863 set width who 10;
2025-07-01 06:04:40.869 -- DO NOT check this! Values can differ here from one run to another!
2025-07-01 06:04:40.877 --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:40.883
2025-07-01 06:04:40.895 rollback;
2025-07-01 06:04:40.905 '''
2025-07-01 06:04:40.912 fn_worker_sql.write_text(worker_sql)
2025-07-01 06:04:40.919
2025-07-01 06:04:40.925 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-01 06:04:40.931
2025-07-01 06:04:40.937 ############################################################################
2025-07-01 06:04:40.943 ### 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:40.949 ############################################################################
2025-07-01 06:04:40.955 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-01 06:04:40.963 '-user', act.db.user,
2025-07-01 06:04:40.973 '-password', act.db.password,
2025-07-01 06:04:40.980 act.db.dsn
2025-07-01 06:04:40.987 ],
2025-07-01 06:04:40.994 stdout = hang_out,
2025-07-01 06:04:41.002 stderr = hang_err
2025-07-01 06:04:41.008 )
2025-07-01 06:04:41.016
2025-07-01 06:04:41.024 # NB: when ISQL will establish attach, first record that it must lock is ID = 5 -- see above SQL_TO_BE_RESTARTED
2025-07-01 06:04:41.032 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:04:41.038 #
2025-07-01 06:04:41.044 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:41.050
2025-07-01 06:04:41.056
2025-07-01 06:04:41.062 #########################
2025-07-01 06:04:41.068 ### L O C K E R - 2 ###
2025-07-01 06:04:41.074 #########################
2025-07-01 06:04:41.080 # Add record so that it **will* be included in the set of rows that must be affected by session-worker:
2025-07-01 06:04:41.085 con_lock_2.execute_immediate( 'insert into test(id, x) values(6, 6);' )
2025-07-01 06:04:41.091 con_lock_2.commit()
2025-07-01 06:04:41.097 con_lock_2.execute_immediate( 'update test set id = id where id = 6;' )
2025-07-01 06:04:41.104
2025-07-01 06:04:41.110 #########################
2025-07-01 06:04:41.122 ### L O C K E R - 1 ###
2025-07-01 06:04:41.131 #########################
2025-07-01 06:04:41.138 con_lock_1.commit() # releases record with ID=1 ==> now it can be locked by worker.
2025-07-01 06:04:41.144
2025-07-01 06:04:41.150 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 1.
2025-07-01 06:04:41.155 #
2025-07-01 06:04:41.161 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:41.167
2025-07-01 06:04:41.173 # If we come here then it means that record with ID = 1 for sure is locked by WORKER.
2025-07-01 06:04:41.179
2025-07-01 06:04:41.185 # Add record so that it **will* be included in the set of rows that must be affected by session-worker:
2025-07-01 06:04:41.191 con_lock_1.execute_immediate( 'insert into test(id, x) values(7, 7);' )
2025-07-01 06:04:41.197 con_lock_1.commit()
2025-07-01 06:04:41.203 con_lock_1.execute_immediate( 'update test set id = id where id = 7;' )
2025-07-01 06:04:41.208
2025-07-01 06:04:41.214 #########################
2025-07-01 06:04:41.220 ### L O C K E R - 2 ###
2025-07-01 06:04:41.225 #########################
2025-07-01 06:04:41.231 con_lock_2.commit() # releases record with ID = 6, but session-worker is waiting for record with ID = 7 (that was added by locker-1).
2025-07-01 06:04:41.240
2025-07-01 06:04:41.250 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 6:
2025-07-01 06:04:41.258 #
2025-07-01 06:04:41.264 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:41.270
2025-07-01 06:04:41.276 # If we come here then it means that record with ID = 6 for sure is locked by WORKER.
2025-07-01 06:04:41.283
2025-07-01 06:04:41.289
2025-07-01 06:04:41.297 con_lock_2.execute_immediate( 'insert into test(id, x) values(8, 8);' )
2025-07-01 06:04:41.304 con_lock_2.commit()
2025-07-01 06:04:41.311 con_lock_2.execute_immediate( 'update test set id = id where id = 8;' )
2025-07-01 06:04:41.318
2025-07-01 06:04:41.326
2025-07-01 06:04:41.337 #########################
2025-07-01 06:04:41.347 ### L O C K E R - 1 ###
2025-07-01 06:04:41.355 #########################
2025-07-01 06:04:41.361 con_lock_1.commit() # releases record with ID = 7, but session-worker is waiting for record with ID = 8 (that was added by locker-2).
2025-07-01 06:04:41.367
2025-07-01 06:04:41.372 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 7:
2025-07-01 06:04:41.378 #
2025-07-01 06:04:41.384 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:41.390
2025-07-01 06:04:41.402 # If we come here then it means that record with ID = 7 for sure is locked by WORKER.
2025-07-01 06:04:41.409
2025-07-01 06:04:41.416 con_lock_1.execute_immediate( 'insert into test(id, x) values(9, 9);' )
2025-07-01 06:04:41.423 con_lock_1.commit()
2025-07-01 06:04:41.429 con_lock_1.execute_immediate( 'update test set id = id where id = 9;' )
2025-07-01 06:04:41.435
2025-07-01 06:04:41.442
2025-07-01 06:04:41.448 #########################
2025-07-01 06:04:41.454 ### L O C K E R - 2 ###
2025-07-01 06:04:41.461 #########################
2025-07-01 06:04:41.467 con_lock_2.commit() # releases record with ID = 8, but session-worker is waiting for record with ID = 9 (that was added by locker-1).
2025-07-01 06:04:41.474
2025-07-01 06:04:41.481 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 8:
2025-07-01 06:04:41.487 #
2025-07-01 06:04:41.494 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 8', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:04:41.499
2025-07-01 06:04:41.511 # If we come here then it means that record with ID = 8 for sure is locked by WORKER.
2025-07-01 06:04:41.520
2025-07-01 06:04:41.526 con_lock_2.execute_immediate( 'insert into test(id, x) values(10, 10);' )
2025-07-01 06:04:41.532 con_lock_2.commit()
2025-07-01 06:04:41.538 con_lock_2.execute_immediate( 'update test set id = id where id = 10;' )
2025-07-01 06:04:41.544
2025-07-01 06:04:41.554
2025-07-01 06:04:41.567 #########################
2025-07-01 06:04:41.577 ### L O C K E R - 1 ###
2025-07-01 06:04:41.589 #########################
2025-07-01 06:04:41.597 con_lock_1.commit() # <<< THIS MUST CANCEL ALL PERFORMED DELETIONS OF SESSION-WORKER: record with ID = 10 become visible to it and its "NOT EXISTS()" query predicate return FAILSE on that.
2025-07-01 06:04:41.603 con_lock_2.commit()
2025-07-01 06:04:41.612
2025-07-01 06:04:41.619 # Here we wait until ISQL complete its mission:
2025-07-01 06:04:41.632 p_worker.wait()
2025-07-01 06:04:41.644
2025-07-01 06:04:41.654 #< with act.db.connect()
2025-07-01 06:04:41.659
2025-07-01 06:04:41.665 for g in (fn_worker_log, fn_worker_err):
2025-07-01 06:04:41.677 with g.open() as f:
2025-07-01 06:04:41.684 for line in f:
2025-07-01 06:04:41.690 if line.split():
2025-07-01 06:04:41.697 if g == fn_worker_log:
2025-07-01 06:04:41.710 print(f'checked_mode: {checked_mode}, STDLOG: {line}')
2025-07-01 06:04:41.723 else:
2025-07-01 06:04:41.732 print(f'UNEXPECTED STDERR {line}')
2025-07-01 06:04:41.739
2025-07-01 06:04:41.748 expected_stdout_worker = f"""
2025-07-01 06:04:41.757 checked_mode: {checked_mode}, STDLOG: Records affected: 0
2025-07-01 06:04:41.765
2025-07-01 06:04:41.778 checked_mode: {checked_mode}, STDLOG: ID
2025-07-01 06:04:41.790 checked_mode: {checked_mode}, STDLOG: =======
2025-07-01 06:04:41.799 checked_mode: {checked_mode}, STDLOG: 1
2025-07-01 06:04:41.807 checked_mode: {checked_mode}, STDLOG: 2
2025-07-01 06:04:41.817 checked_mode: {checked_mode}, STDLOG: 3
2025-07-01 06:04:41.830 checked_mode: {checked_mode}, STDLOG: 4
2025-07-01 06:04:41.841 checked_mode: {checked_mode}, STDLOG: 5
2025-07-01 06:04:41.854 checked_mode: {checked_mode}, STDLOG: 6
2025-07-01 06:04:41.864 checked_mode: {checked_mode}, STDLOG: 7
2025-07-01 06:04:41.872 checked_mode: {checked_mode}, STDLOG: 8
2025-07-01 06:04:41.879 checked_mode: {checked_mode}, STDLOG: 9
2025-07-01 06:04:41.886 checked_mode: {checked_mode}, STDLOG: 10
2025-07-01 06:04:41.892 checked_mode: {checked_mode}, STDLOG: Records affected: 10
2025-07-01 06:04:41.898
2025-07-01 06:04:41.904 checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:04:41.915 checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
2025-07-01 06:04:41.925 checked_mode: {checked_mode}, STDLOG: 5 DEL 1
2025-07-01 06:04:41.932 checked_mode: {checked_mode}, STDLOG: 4 DEL 1
2025-07-01 06:04:41.938 checked_mode: {checked_mode}, STDLOG: 3 DEL 1
2025-07-01 06:04:41.945 checked_mode: {checked_mode}, STDLOG: 2 DEL 1
2025-07-01 06:04:41.951
2025-07-01 06:04:41.959 checked_mode: {checked_mode}, STDLOG: Records affected: 4
2025-07-01 06:04:41.967 """
2025-07-01 06:04:41.977 act.expected_stdout = expected_stdout_worker
2025-07-01 06:04:41.985 act.stdout = capsys.readouterr().out
2025-07-01 06:04:41.990 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-01 06:04:41.996 E assert
2025-07-01 06:04:42.002 E checked_mode: table, STDLOG: Records affected: 0
2025-07-01 06:04:42.009 E checked_mode: table, STDLOG: ID
2025-07-01 06:04:42.015 E checked_mode: table, STDLOG:
2025-07-01 06:04:42.022 E checked_mode: table, STDLOG: 1
2025-07-01 06:04:42.028 E checked_mode: table, STDLOG: 2
2025-07-01 06:04:42.036 E checked_mode: table, STDLOG: 3
2025-07-01 06:04:42.043 E checked_mode: table, STDLOG: 4
2025-07-01 06:04:42.051 E checked_mode: table, STDLOG: 5
2025-07-01 06:04:42.057 E checked_mode: table, STDLOG: 6
2025-07-01 06:04:42.063 E checked_mode: table, STDLOG: 7
2025-07-01 06:04:42.069 E checked_mode: table, STDLOG: 8
2025-07-01 06:04:42.076 E checked_mode: table, STDLOG: 9
2025-07-01 06:04:42.082 E checked_mode: table, STDLOG: 10
2025-07-01 06:04:42.088 E checked_mode: table, STDLOG: Records affected: 10
2025-07-01 06:04:42.094 E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:04:42.100 E checked_mode: table, STDLOG:
2025-07-01 06:04:42.106 E - checked_mode: table, STDLOG: 5 DEL 1
2025-07-01 06:04:42.126 E + checked_mode: table, STDLOG: 5DEL 1
2025-07-01 06:04:42.135 E - checked_mode: table, STDLOG: 4 DEL 1
2025-07-01 06:04:42.153 E + checked_mode: table, STDLOG: 4DEL 1
2025-07-01 06:04:42.160 E - checked_mode: table, STDLOG: 3 DEL 1
2025-07-01 06:04:42.174 E + checked_mode: table, STDLOG: 3DEL 1
2025-07-01 06:04:42.185 E - checked_mode: table, STDLOG: 2 DEL 1
2025-07-01 06:04:42.209 E + checked_mode: table, STDLOG: 2DEL 1
2025-07-01 06:04:42.220 E checked_mode: table, STDLOG: Records affected: 4
2025-07-01 06:04:42.228
2025-07-01 06:04:42.236 tests/functional/transactions/test_read_consist_statement_delete_undone_01.py:449: AssertionError
2025-07-01 06:04:42.242 ---------------------------- Captured stdout setup -----------------------------
2025-07-01 06:04:42.249 Creating db: localhost:/var/tmp/qa_2024/test_12472/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_12472/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12472/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12472/tmp_worker.err')
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>
@pytest.mark.trace
@pytest.mark.version('>=4.0.3')
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} where not exists(select * from {target_obj} where id >= 10) order by id desc'
# add rows with ID = 1,2,3,4,5:
sql_addi='''
set term ^;
execute block as
begin
rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
end
^
set term ;^
insert into test(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( 'update test 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;
set list off;
set wng off;
set count on;
-- this must hang because of locker-1:
{SQL_TO_BE_RESTARTED};
-- check results:
-- ###############
select id from test 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 = 5 -- 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=5', SQL_TAG_THAT_WE_WAITING_FOR)
#########################
### L O C K E R - 2 ###
#########################
# Add record so that it **will* be included in the set of rows that must be affected by session-worker:
con_lock_2.execute_immediate( 'insert into test(id, x) values(6, 6);' )
con_lock_2.commit()
con_lock_2.execute_immediate( 'update test set id = id where id = 6;' )
#########################
### 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.
# Add record so that it **will* be included in the set of rows that must be affected by session-worker:
con_lock_1.execute_immediate( 'insert into test(id, x) values(7, 7);' )
con_lock_1.commit()
con_lock_1.execute_immediate( 'update test set id = id where id = 7;' )
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.commit() # releases record with ID = 6, but session-worker is waiting for record with ID = 7 (that was added by locker-1).
# 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( 'insert into test(id, x) values(8, 8);' )
con_lock_2.commit()
con_lock_2.execute_immediate( 'update test set id = id where id = 8;' )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # releases record with ID = 7, but session-worker is waiting for record with ID = 8 (that was added by locker-2).
# 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( 'insert into test(id, x) values(9, 9);' )
con_lock_1.commit()
con_lock_1.execute_immediate( 'update test set id = id where id = 9;' )
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.commit() # releases record with ID = 8, but session-worker is waiting for record with ID = 9 (that was added by locker-1).
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = 8:
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 8', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = 8 for sure is locked by WORKER.
con_lock_2.execute_immediate( 'insert into test(id, x) values(10, 10);' )
con_lock_2.commit()
con_lock_2.execute_immediate( 'update test set id = id where id = 10;' )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # <<< THIS MUST CANCEL ALL PERFORMED DELETIONS OF SESSION-WORKER: record with ID = 10 become visible to it and its "NOT EXISTS()" query predicate return FAILSE on that.
con_lock_2.commit()
# Here we wait until 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: 0
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: 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: 9
checked_mode: {checked_mode}, STDLOG: 10
checked_mode: {checked_mode}, STDLOG: Records affected: 10
checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, STDLOG: 5 DEL 1
checked_mode: {checked_mode}, STDLOG: 4 DEL 1
checked_mode: {checked_mode}, STDLOG: 3 DEL 1
checked_mode: {checked_mode}, STDLOG: 2 DEL 1
checked_mode: {checked_mode}, STDLOG: Records affected: 4
"""
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: 0
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: 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: 9
E checked_mode: table, STDLOG: 10
E checked_mode: table, STDLOG: Records affected: 10
E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
E checked_mode: table, STDLOG:
E - checked_mode: table, STDLOG: 5 DEL 1
E + checked_mode: table, STDLOG: 5DEL 1
E - checked_mode: table, STDLOG: 4 DEL 1
E + checked_mode: table, STDLOG: 4DEL 1
E - checked_mode: table, STDLOG: 3 DEL 1
E + checked_mode: table, STDLOG: 3DEL 1
E - checked_mode: table, STDLOG: 2 DEL 1
E + checked_mode: table, STDLOG: 2DEL 1
E checked_mode: table, STDLOG: Records affected: 4
tests/functional/transactions/test_read_consist_statement_delete_undone_01.py:449: AssertionError
|