2 @message |
assert
checked_mode: table, STDLOG: Records affected: 8
checked_mode: table, STDLOG: ID
checked_mode: table, STDLOG:
checked_mode: table, STDLOG: -5
checked_mode: table, STDLOG: -4
checked_mode: table, STDLOG: -3
checked_mode: table, STDLOG: -2
checked_mode: table, STDLOG: -1
checked_mode: table, STDLOG: 11
checked_mode: table, STDLOG: 12
checked_mode: table, STDLOG: 13
checked_mode: table, STDLOG: Records affected: 8
checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: table, STDLOG:
- checked_mode: table, STDLOG: 1 UPD 1
+ checked_mode: table, STDLOG: 1UPD 1
- checked_mode: table, STDLOG: 2 UPD 1
+ checked_mode: table, STDLOG: 2UPD 1
- checked_mode: table, STDLOG: 3 UPD 1
+ checked_mode: table, STDLOG: 3UPD 1
- checked_mode: table, STDLOG: 4 UPD 1
+ checked_mode: table, STDLOG: 4UPD 1
- checked_mode: table, STDLOG: -13 UPD 2
+ checked_mode: table, STDLOG: -13UPD 2
- checked_mode: table, STDLOG: -12 UPD 2
+ checked_mode: table, STDLOG: -12UPD 2
- checked_mode: table, STDLOG: -11 UPD 2
+ checked_mode: table, STDLOG: -11UPD 2
- checked_mode: table, STDLOG: 1 UPD 2
+ checked_mode: table, STDLOG: 1UPD 2
- checked_mode: table, STDLOG: 2 UPD 2
+ checked_mode: table, STDLOG: 2UPD 2
- checked_mode: table, STDLOG: 3 UPD 2
+ checked_mode: table, STDLOG: 3UPD 2
- checked_mode: table, STDLOG: 4 UPD 2
+ checked_mode: table, STDLOG: 4UPD 2
- checked_mode: table, STDLOG: 5 UPD 2
+ checked_mode: table, STDLOG: 5UPD 2
checked_mode: table, STDLOG: Records affected: 12
LOG DETAILS:
2025-07-01 06:05:06.877
2025-07-01 06:05:06.889 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-01 06:05:06.897 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12484/tmp_worker.sql')
2025-07-01 06:05:06.906 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12484/tmp_worker.log')
2025-07-01 06:05:06.913 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12484/tmp_worker.err')
2025-07-01 06:05:06.920 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-01 06:05:06.927
2025-07-01 06:05:06.934 @pytest.mark.trace
2025-07-01 06:05:06.940 @pytest.mark.version('>=4.0.2')
2025-07-01 06:05:06.947 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-01 06:05:06.955 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-01 06:05:06.965
2025-07-01 06:05:06.973 for checked_mode in('table', 'view'):
2025-07-01 06:05:06.980 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-01 06:05:06.986
2025-07-01 06:05:06.995 SQL_TO_BE_RESTARTED = f"update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = -id order by id"
2025-07-01 06:05:07.004
2025-07-01 06:05:07.012 # add rows with ID = 1, 2, ..., 5:
2025-07-01 06:05:07.019 sql_addi = f'''
2025-07-01 06:05:07.027 set term ^;
2025-07-01 06:05:07.033 execute block as
2025-07-01 06:05:07.040 begin
2025-07-01 06:05:07.048 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-01 06:05:07.055 end
2025-07-01 06:05:07.061 ^
2025-07-01 06:05:07.068 set term ;^
2025-07-01 06:05:07.075 insert into {target_obj}(id, x)
2025-07-01 06:05:07.082 select row_number()over(),row_number()over()
2025-07-01 06:05:07.089 from rdb$types rows 5;
2025-07-01 06:05:07.096 commit;
2025-07-01 06:05:07.101 '''
2025-07-01 06:05:07.106
2025-07-01 06:05:07.112 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-07-01 06:05:07.118 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-01 06:05:07.124 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-01 06:05:07.130 assert act.stderr == ''
2025-07-01 06:05:07.140 act.reset()
2025-07-01 06:05:07.150
2025-07-01 06:05:07.157 trace_cfg_items = [
2025-07-01 06:05:07.163 'time_threshold = 0',
2025-07-01 06:05:07.171 'log_errors = true',
2025-07-01 06:05:07.181 'log_statement_start = true',
2025-07-01 06:05:07.190 'log_statement_finish = true',
2025-07-01 06:05:07.198 ]
2025-07-01 06:05:07.208
2025-07-01 06:05:07.217 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-01 06:05:07.223
2025-07-01 06:05:07.230 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:05:07.235
2025-07-01 06:05:07.242 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-01 06:05:07.247 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-01 06:05:07.253 cur_monitoring = tx_monitoring.cursor()
2025-07-01 06:05:07.259
2025-07-01 06:05:07.265 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-01 06:05:07.271 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-01 06:05:07.276 c.execute_immediate(sttm)
2025-07-01 06:05:07.282
2025-07-01 06:05:07.287 #########################
2025-07-01 06:05:07.295 ### L O C K E R - 1 ###
2025-07-01 06:05:07.305 #########################
2025-07-01 06:05:07.315
2025-07-01 06:05:07.322 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = 5' )
2025-07-01 06:05:07.332
2025-07-01 06:05:07.343 worker_sql = f'''
2025-07-01 06:05:07.353 set list on;
2025-07-01 06:05:07.362 set autoddl off;
2025-07-01 06:05:07.370 set term ^;
2025-07-01 06:05:07.375 execute block returns (whoami varchar(30)) as
2025-07-01 06:05:07.380 begin
2025-07-01 06:05:07.384 whoami = 'WORKER'; -- , ATT#' || current_connection;
2025-07-01 06:05:07.390 rdb$set_context('USER_SESSION','WHO', whoami);
2025-07-01 06:05:07.395 -- suspend;
2025-07-01 06:05:07.401 end
2025-07-01 06:05:07.406 ^
2025-07-01 06:05:07.417 set term ;^
2025-07-01 06:05:07.427 commit;
2025-07-01 06:05:07.436
2025-07-01 06:05:07.444 SET KEEP_TRAN_PARAMS ON;
2025-07-01 06:05:07.451 set transaction read committed read consistency;
2025-07-01 06:05:07.460 set list off;
2025-07-01 06:05:07.473 set wng off;
2025-07-01 06:05:07.482 set count on;
2025-07-01 06:05:07.488
2025-07-01 06:05:07.495 -- THIS MUST BE LOCKED:
2025-07-01 06:05:07.501 {SQL_TO_BE_RESTARTED};
2025-07-01 06:05:07.507
2025-07-01 06:05:07.516 -- check results:
2025-07-01 06:05:07.526 -- ###############
2025-07-01 06:05:07.533 select id from {target_obj} order by id; -- this will produce output only after all lockers do their commit/rollback
2025-07-01 06:05:07.538
2025-07-01 06:05:07.544 select v.old_id, v.op, v.snap_no_rank
2025-07-01 06:05:07.556 from v_worker_log v
2025-07-01 06:05:07.567 where v.op = 'upd';
2025-07-01 06:05:07.575
2025-07-01 06:05:07.582 set width who 10;
2025-07-01 06:05:07.591 -- DO NOT check this! Values can differ here from one run to another!
2025-07-01 06:05:07.601 -- 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:05:07.609
2025-07-01 06:05:07.615 rollback;
2025-07-01 06:05:07.621
2025-07-01 06:05:07.626 '''
2025-07-01 06:05:07.630
2025-07-01 06:05:07.635 fn_worker_sql.write_text(worker_sql)
2025-07-01 06:05:07.640
2025-07-01 06:05:07.646 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-01 06:05:07.652
2025-07-01 06:05:07.658 ############################################################################
2025-07-01 06:05:07.666 ### 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:05:07.679 ############################################################################
2025-07-01 06:05:07.687 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-01 06:05:07.695 '-user', act.db.user,
2025-07-01 06:05:07.702 '-password', act.db.password,
2025-07-01 06:05:07.711 '-pag', '999999',
2025-07-01 06:05:07.722 act.db.dsn
2025-07-01 06:05:07.731 ],
2025-07-01 06:05:07.738 stdout = hang_out,
2025-07-01 06:05:07.748 stderr = hang_err
2025-07-01 06:05:07.757 )
2025-07-01 06:05:07.764
2025-07-01 06:05:07.771 # 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:05:07.778 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:05:07.783 #
2025-07-01 06:05:07.790 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:05:07.796
2025-07-01 06:05:07.803
2025-07-01 06:05:07.815 #########################
2025-07-01 06:05:07.826 ### L O C K E R - 2 ###
2025-07-01 06:05:07.834 #########################
2025-07-01 06:05:07.840
2025-07-01 06:05:07.846 # Add record with such ID that it **will* be included in the set of rows that must be affected by session-worker:
2025-07-01 06:05:07.853 con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(-11)')
2025-07-01 06:05:07.860 con_lock_2.commit()
2025-07-01 06:05:07.867 con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = -11')
2025-07-01 06:05:07.875
2025-07-01 06:05:07.886 #########################
2025-07-01 06:05:07.892 ### L O C K E R - 1 ###
2025-07-01 06:05:07.901 #########################
2025-07-01 06:05:07.909 con_lock_1.commit() # releases record with ID = 5 ==> now it can be locked by worker.
2025-07-01 06:05:07.916
2025-07-01 06:05:07.922 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 5.
2025-07-01 06:05:07.931 #
2025-07-01 06:05:07.941 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:05:07.948 # If we come here then it means that record with ID = 5 for sure is locked by WORKER.
2025-07-01 06:05:07.955
2025-07-01 06:05:07.962 con_lock_1.execute_immediate( f'insert into {target_obj}(id) values(-12)' )
2025-07-01 06:05:07.974 con_lock_1.commit()
2025-07-01 06:05:07.982 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = -12' )
2025-07-01 06:05:07.989
2025-07-01 06:05:07.996
2025-07-01 06:05:08.002 #########################
2025-07-01 06:05:08.008 ### L O C K E R - 2 ###
2025-07-01 06:05:08.014 #########################
2025-07-01 06:05:08.021 con_lock_2.commit() # releases record with ID = -11 ==> now it can be locked by worker.
2025-07-01 06:05:08.028
2025-07-01 06:05:08.036 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = -11:
2025-07-01 06:05:08.043 #
2025-07-01 06:05:08.049 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = -11', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:05:08.055 # If we come here then it means that record with ID = -11 for sure is locked by WORKER.
2025-07-01 06:05:08.061
2025-07-01 06:05:08.067
2025-07-01 06:05:08.073 con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(-13)' )
2025-07-01 06:05:08.079 con_lock_2.commit()
2025-07-01 06:05:08.087 con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = -13' )
2025-07-01 06:05:08.095
2025-07-01 06:05:08.106 #########################
2025-07-01 06:05:08.114 ### L O C K E R - 1 ###
2025-07-01 06:05:08.120 #########################
2025-07-01 06:05:08.132 con_lock_1.commit() # releases record with ID = -12 ==> now it can be locked by worker.
2025-07-01 06:05:08.142
2025-07-01 06:05:08.152 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = -12:
2025-07-01 06:05:08.159 #
2025-07-01 06:05:08.167 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = -12', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:05:08.179 # If we come here then it means that record with ID = -12 for sure is locked by WORKER.
2025-07-01 06:05:08.189
2025-07-01 06:05:08.200 #########################
2025-07-01 06:05:08.209 ### L O C K E R - 2 ###
2025-07-01 06:05:08.220 #########################
2025-07-01 06:05:08.231 con_lock_2.commit() # WORKER will complete his job after this
2025-07-01 06:05:08.238
2025-07-01 06:05:08.244
2025-07-01 06:05:08.250 # Here we wait for ISQL complete its mission:
2025-07-01 06:05:08.263 p_worker.wait()
2025-07-01 06:05:08.274
2025-07-01 06:05:08.281 #< with act.db.connect()
2025-07-01 06:05:08.286
2025-07-01 06:05:08.293 for g in (fn_worker_log, fn_worker_err):
2025-07-01 06:05:08.299 with g.open() as f:
2025-07-01 06:05:08.304 for line in f:
2025-07-01 06:05:08.308 if line.split():
2025-07-01 06:05:08.313 if g == fn_worker_log:
2025-07-01 06:05:08.318 print(f'checked_mode: {checked_mode}, STDLOG: {line}')
2025-07-01 06:05:08.326 else:
2025-07-01 06:05:08.336 print(f'UNEXPECTED STDERR {line}')
2025-07-01 06:05:08.344
2025-07-01 06:05:08.351 expected_stdout_worker = f"""
2025-07-01 06:05:08.359 checked_mode: {checked_mode}, STDLOG: Records affected: 8
2025-07-01 06:05:08.371
2025-07-01 06:05:08.384 checked_mode: {checked_mode}, STDLOG: ID
2025-07-01 06:05:08.395 checked_mode: {checked_mode}, STDLOG: =======
2025-07-01 06:05:08.406 checked_mode: {checked_mode}, STDLOG: -5
2025-07-01 06:05:08.415 checked_mode: {checked_mode}, STDLOG: -4
2025-07-01 06:05:08.423 checked_mode: {checked_mode}, STDLOG: -3
2025-07-01 06:05:08.433 checked_mode: {checked_mode}, STDLOG: -2
2025-07-01 06:05:08.441 checked_mode: {checked_mode}, STDLOG: -1
2025-07-01 06:05:08.448 checked_mode: {checked_mode}, STDLOG: 11
2025-07-01 06:05:08.454 checked_mode: {checked_mode}, STDLOG: 12
2025-07-01 06:05:08.461 checked_mode: {checked_mode}, STDLOG: 13
2025-07-01 06:05:08.467 checked_mode: {checked_mode}, STDLOG: Records affected: 8
2025-07-01 06:05:08.479
2025-07-01 06:05:08.489 checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:05:08.501 checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
2025-07-01 06:05:08.512 checked_mode: {checked_mode}, STDLOG: 1 UPD 1
2025-07-01 06:05:08.525 checked_mode: {checked_mode}, STDLOG: 2 UPD 1
2025-07-01 06:05:08.538 checked_mode: {checked_mode}, STDLOG: 3 UPD 1
2025-07-01 06:05:08.550 checked_mode: {checked_mode}, STDLOG: 4 UPD 1
2025-07-01 06:05:08.559 checked_mode: {checked_mode}, STDLOG: -13 UPD 2
2025-07-01 06:05:08.566 checked_mode: {checked_mode}, STDLOG: -12 UPD 2
2025-07-01 06:05:08.573 checked_mode: {checked_mode}, STDLOG: -11 UPD 2
2025-07-01 06:05:08.580 checked_mode: {checked_mode}, STDLOG: 1 UPD 2
2025-07-01 06:05:08.587 checked_mode: {checked_mode}, STDLOG: 2 UPD 2
2025-07-01 06:05:08.594 checked_mode: {checked_mode}, STDLOG: 3 UPD 2
2025-07-01 06:05:08.604 checked_mode: {checked_mode}, STDLOG: 4 UPD 2
2025-07-01 06:05:08.614 checked_mode: {checked_mode}, STDLOG: 5 UPD 2
2025-07-01 06:05:08.623 checked_mode: {checked_mode}, STDLOG: Records affected: 12
2025-07-01 06:05:08.631 """
2025-07-01 06:05:08.638
2025-07-01 06:05:08.645 act.expected_stdout = expected_stdout_worker
2025-07-01 06:05:08.652 act.stdout = capsys.readouterr().out
2025-07-01 06:05:08.659 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-01 06:05:08.664 E assert
2025-07-01 06:05:08.669 E checked_mode: table, STDLOG: Records affected: 8
2025-07-01 06:05:08.673 E checked_mode: table, STDLOG: ID
2025-07-01 06:05:08.678 E checked_mode: table, STDLOG:
2025-07-01 06:05:08.682 E checked_mode: table, STDLOG: -5
2025-07-01 06:05:08.687 E checked_mode: table, STDLOG: -4
2025-07-01 06:05:08.691 E checked_mode: table, STDLOG: -3
2025-07-01 06:05:08.696 E checked_mode: table, STDLOG: -2
2025-07-01 06:05:08.702 E checked_mode: table, STDLOG: -1
2025-07-01 06:05:08.707 E checked_mode: table, STDLOG: 11
2025-07-01 06:05:08.712 E checked_mode: table, STDLOG: 12
2025-07-01 06:05:08.717 E checked_mode: table, STDLOG: 13
2025-07-01 06:05:08.721 E checked_mode: table, STDLOG: Records affected: 8
2025-07-01 06:05:08.726 E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:05:08.731 E checked_mode: table, STDLOG:
2025-07-01 06:05:08.736 E - checked_mode: table, STDLOG: 1 UPD 1
2025-07-01 06:05:08.746 E + checked_mode: table, STDLOG: 1UPD 1
2025-07-01 06:05:08.751 E - checked_mode: table, STDLOG: 2 UPD 1
2025-07-01 06:05:08.762 E + checked_mode: table, STDLOG: 2UPD 1
2025-07-01 06:05:08.769 E - checked_mode: table, STDLOG: 3 UPD 1
2025-07-01 06:05:08.779 E + checked_mode: table, STDLOG: 3UPD 1
2025-07-01 06:05:08.786 E - checked_mode: table, STDLOG: 4 UPD 1
2025-07-01 06:05:08.800 E + checked_mode: table, STDLOG: 4UPD 1
2025-07-01 06:05:08.807 E - checked_mode: table, STDLOG: -13 UPD 2
2025-07-01 06:05:08.821 E + checked_mode: table, STDLOG: -13UPD 2
2025-07-01 06:05:08.827 E - checked_mode: table, STDLOG: -12 UPD 2
2025-07-01 06:05:08.839 E + checked_mode: table, STDLOG: -12UPD 2
2025-07-01 06:05:08.845 E - checked_mode: table, STDLOG: -11 UPD 2
2025-07-01 06:05:08.855 E + checked_mode: table, STDLOG: -11UPD 2
2025-07-01 06:05:08.860 E - checked_mode: table, STDLOG: 1 UPD 2
2025-07-01 06:05:08.876 E + checked_mode: table, STDLOG: 1UPD 2
2025-07-01 06:05:08.885 E - checked_mode: table, STDLOG: 2 UPD 2
2025-07-01 06:05:08.899 E + checked_mode: table, STDLOG: 2UPD 2
2025-07-01 06:05:08.904 E - checked_mode: table, STDLOG: 3 UPD 2
2025-07-01 06:05:08.916 E + checked_mode: table, STDLOG: 3UPD 2
2025-07-01 06:05:08.922 E - checked_mode: table, STDLOG: 4 UPD 2
2025-07-01 06:05:08.944 E + checked_mode: table, STDLOG: 4UPD 2
2025-07-01 06:05:08.956 E - checked_mode: table, STDLOG: 5 UPD 2
2025-07-01 06:05:08.981 E + checked_mode: table, STDLOG: 5UPD 2
2025-07-01 06:05:08.989 E checked_mode: table, STDLOG: Records affected: 12
2025-07-01 06:05:08.996
2025-07-01 06:05:09.003 tests/functional/transactions/test_read_consist_sttm_restart_on_update_01.py:440: AssertionError
2025-07-01 06:05:09.008 ---------------------------- Captured stdout setup -----------------------------
2025-07-01 06:05:09.013 Creating db: localhost:/var/tmp/qa_2024/test_12484/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_12484/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12484/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12484/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"update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = -id order by id"
# add rows with ID = 1, 2, ..., 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 KEEP_TRAN_PARAMS ON;
set transaction read committed read consistency;
set list off;
set wng off;
set count on;
-- 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 = '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 = 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 ###
#########################
# Add record with such ID that it **will* be included in the set of rows that must be affected by session-worker:
con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(-11)')
con_lock_2.commit()
con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = -11')
#########################
### 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(-12)' )
con_lock_1.commit()
con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = -12' )
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.commit() # releases record with ID = -11 ==> now it can be locked by worker.
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = -11:
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = -11', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = -11 for sure is locked by WORKER.
con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(-13)' )
con_lock_2.commit()
con_lock_2.execute_immediate( f'update {target_obj} set id=id where id = -13' )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # releases record with ID = -12 ==> now it can be locked by worker.
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = -12:
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = -12', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = -12 for sure is locked by WORKER.
#########################
### L O C K E R - 2 ###
#########################
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: 8
checked_mode: {checked_mode}, STDLOG: ID
checked_mode: {checked_mode}, STDLOG: =======
checked_mode: {checked_mode}, STDLOG: -5
checked_mode: {checked_mode}, STDLOG: -4
checked_mode: {checked_mode}, STDLOG: -3
checked_mode: {checked_mode}, STDLOG: -2
checked_mode: {checked_mode}, STDLOG: -1
checked_mode: {checked_mode}, STDLOG: 11
checked_mode: {checked_mode}, STDLOG: 12
checked_mode: {checked_mode}, STDLOG: 13
checked_mode: {checked_mode}, STDLOG: Records affected: 8
checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, STDLOG: 1 UPD 1
checked_mode: {checked_mode}, STDLOG: 2 UPD 1
checked_mode: {checked_mode}, STDLOG: 3 UPD 1
checked_mode: {checked_mode}, STDLOG: 4 UPD 1
checked_mode: {checked_mode}, STDLOG: -13 UPD 2
checked_mode: {checked_mode}, STDLOG: -12 UPD 2
checked_mode: {checked_mode}, STDLOG: -11 UPD 2
checked_mode: {checked_mode}, STDLOG: 1 UPD 2
checked_mode: {checked_mode}, STDLOG: 2 UPD 2
checked_mode: {checked_mode}, STDLOG: 3 UPD 2
checked_mode: {checked_mode}, STDLOG: 4 UPD 2
checked_mode: {checked_mode}, STDLOG: 5 UPD 2
checked_mode: {checked_mode}, STDLOG: Records affected: 12
"""
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: 8
E checked_mode: table, STDLOG: ID
E checked_mode: table, STDLOG:
E checked_mode: table, STDLOG: -5
E checked_mode: table, STDLOG: -4
E checked_mode: table, STDLOG: -3
E checked_mode: table, STDLOG: -2
E checked_mode: table, STDLOG: -1
E checked_mode: table, STDLOG: 11
E checked_mode: table, STDLOG: 12
E checked_mode: table, STDLOG: 13
E checked_mode: table, STDLOG: Records affected: 8
E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
E checked_mode: table, STDLOG:
E - checked_mode: table, STDLOG: 1 UPD 1
E + checked_mode: table, STDLOG: 1UPD 1
E - checked_mode: table, STDLOG: 2 UPD 1
E + checked_mode: table, STDLOG: 2UPD 1
E - checked_mode: table, STDLOG: 3 UPD 1
E + checked_mode: table, STDLOG: 3UPD 1
E - checked_mode: table, STDLOG: 4 UPD 1
E + checked_mode: table, STDLOG: 4UPD 1
E - checked_mode: table, STDLOG: -13 UPD 2
E + checked_mode: table, STDLOG: -13UPD 2
E - checked_mode: table, STDLOG: -12 UPD 2
E + checked_mode: table, STDLOG: -12UPD 2
E - checked_mode: table, STDLOG: -11 UPD 2
E + checked_mode: table, STDLOG: -11UPD 2
E - checked_mode: table, STDLOG: 1 UPD 2
E + checked_mode: table, STDLOG: 1UPD 2
E - checked_mode: table, STDLOG: 2 UPD 2
E + checked_mode: table, STDLOG: 2UPD 2
E - checked_mode: table, STDLOG: 3 UPD 2
E + checked_mode: table, STDLOG: 3UPD 2
E - checked_mode: table, STDLOG: 4 UPD 2
E + checked_mode: table, STDLOG: 4UPD 2
E - checked_mode: table, STDLOG: 5 UPD 2
E + checked_mode: table, STDLOG: 5UPD 2
E checked_mode: table, STDLOG: Records affected: 12
tests/functional/transactions/test_read_consist_sttm_restart_on_update_01.py:440: AssertionError
|