2 @message |
assert
checked_mode: table, STDLOG: Records affected: 10
checked_mode: table, STDLOG: ID
checked_mode: table, STDLOG:
checked_mode: table, STDLOG: -140
checked_mode: table, STDLOG: -130
checked_mode: table, STDLOG: -120
checked_mode: table, STDLOG: -110
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: 14
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: 1 UPD 1
+ checked_mode: table, STDLOG: 1UPD 1
- checked_mode: table, STDLOG: -14 UPD 2
+ checked_mode: table, STDLOG: -14UPD 2
- 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: 110 UPD 2
+ checked_mode: table, STDLOG: 110UPD 2
- checked_mode: table, STDLOG: 120 UPD 2
+ checked_mode: table, STDLOG: 120UPD 2
- checked_mode: table, STDLOG: 130 UPD 2
+ checked_mode: table, STDLOG: 130UPD 2
- checked_mode: table, STDLOG: 140 UPD 2
+ checked_mode: table, STDLOG: 140UPD 2
checked_mode: table, STDLOG: Records affected: 11
LOG DETAILS:
2025-07-02 06:07:58.206
2025-07-02 06:07:58.213 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-02 06:07:58.219 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12487/tmp_worker.sql')
2025-07-02 06:07:58.225 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12487/tmp_worker.log')
2025-07-02 06:07:58.230 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12487/tmp_worker.err')
2025-07-02 06:07:58.238 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-02 06:07:58.248
2025-07-02 06:07:58.258 @pytest.mark.trace
2025-07-02 06:07:58.266 @pytest.mark.version('>=4.0.2')
2025-07-02 06:07:58.276 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-02 06:07:58.285 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-02 06:07:58.293
2025-07-02 06:07:58.299 for checked_mode in('table', 'view'):
2025-07-02 06:07:58.305 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-02 06:07:58.310
2025-07-02 06:07:58.315 SQL_TO_BE_RESTARTED = f"update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = -id order by id ROWS 10"
2025-07-02 06:07:58.320
2025-07-02 06:07:58.325 # add rows with ID = 1, 2:
2025-07-02 06:07:58.330 sql_addi = f'''
2025-07-02 06:07:58.337 set term ^;
2025-07-02 06:07:58.343 execute block as
2025-07-02 06:07:58.355 begin
2025-07-02 06:07:58.365 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-02 06:07:58.373 end
2025-07-02 06:07:58.380 ^
2025-07-02 06:07:58.387 set term ;^
2025-07-02 06:07:58.395 insert into {target_obj}(id, x) select row_number()over(),row_number()over() from rdb$types rows 2;
2025-07-02 06:07:58.403 commit;
2025-07-02 06:07:58.414 '''
2025-07-02 06:07:58.424
2025-07-02 06:07:58.432 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-07-02 06:07:58.440 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-02 06:07:58.447 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-02 06:07:58.453 assert act.stderr == ''
2025-07-02 06:07:58.459 act.reset()
2025-07-02 06:07:58.466
2025-07-02 06:07:58.478 trace_cfg_items = [
2025-07-02 06:07:58.487 'time_threshold = 0',
2025-07-02 06:07:58.495 'log_errors = true',
2025-07-02 06:07:58.503 'log_statement_start = true',
2025-07-02 06:07:58.510 'log_statement_finish = true',
2025-07-02 06:07:58.516 ]
2025-07-02 06:07:58.522
2025-07-02 06:07:58.528 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-02 06:07:58.533
2025-07-02 06:07:58.539 with act.db.connect() as con_lock_1, act.db.connect() as con_lock_2, act.db.connect() as con_monitoring:
2025-07-02 06:07:58.546
2025-07-02 06:07:58.553 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-02 06:07:58.560 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-02 06:07:58.566 cur_monitoring = tx_monitoring.cursor()
2025-07-02 06:07:58.575
2025-07-02 06:07:58.585 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-02 06:07:58.595 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-02 06:07:58.604 c.execute_immediate(sttm)
2025-07-02 06:07:58.615
2025-07-02 06:07:58.628 #########################
2025-07-02 06:07:58.640 ### L O C K E R - 1 ###
2025-07-02 06:07:58.654 #########################
2025-07-02 06:07:58.664
2025-07-02 06:07:58.677 con_lock_1.execute_immediate( f'update /* LOCKER-1 */ {target_obj} set id=id where id = 2' )
2025-07-02 06:07:58.689
2025-07-02 06:07:58.697 worker_sql = f'''
2025-07-02 06:07:58.705 set list on;
2025-07-02 06:07:58.716 set autoddl off;
2025-07-02 06:07:58.725 set term ^;
2025-07-02 06:07:58.736 execute block returns (whoami varchar(30)) as
2025-07-02 06:07:58.745 begin
2025-07-02 06:07:58.753 whoami = 'WORKER'; -- , ATT#' || current_connection;
2025-07-02 06:07:58.760 rdb$set_context('USER_SESSION','WHO', whoami);
2025-07-02 06:07:58.766 -- suspend;
2025-07-02 06:07:58.771 end
2025-07-02 06:07:58.777 ^
2025-07-02 06:07:58.783 set term ;^
2025-07-02 06:07:58.791 commit;
2025-07-02 06:07:58.801 SET KEEP_TRAN_PARAMS ON;
2025-07-02 06:07:58.809 set transaction read committed read consistency;
2025-07-02 06:07:58.816 set list off;
2025-07-02 06:07:58.822 set wng off;
2025-07-02 06:07:58.833 set count on;
2025-07-02 06:07:58.842
2025-07-02 06:07:58.849 -- WORKER. THIS MUST BE LOCKED NOW BY LOCKER_i:
2025-07-02 06:07:58.856 {SQL_TO_BE_RESTARTED};
2025-07-02 06:07:58.862
2025-07-02 06:07:58.870 -- check results:
2025-07-02 06:07:58.881 -- ###############
2025-07-02 06:07:58.889 select id from {target_obj} order by id; -- this will produce output only after all lockers do their commit/rollback
2025-07-02 06:07:58.895
2025-07-02 06:07:58.901 select v.old_id, v.op, v.snap_no_rank from v_worker_log v where v.op = 'upd';
2025-07-02 06:07:58.906
2025-07-02 06:07:58.917 set width who 10;
2025-07-02 06:07:58.930 -- DO NOT check this! Values can differ here from one run to another!
2025-07-02 06:07:58.942 -- select id, trn, who, old_id, new_id, op, rec_vers, global_cn, snap_no from tlog_done order by id;
2025-07-02 06:07:58.955
2025-07-02 06:07:58.966 rollback;
2025-07-02 06:07:58.977
2025-07-02 06:07:58.988 '''
2025-07-02 06:07:58.999
2025-07-02 06:07:59.012 fn_worker_sql.write_text(worker_sql)
2025-07-02 06:07:59.024
2025-07-02 06:07:59.038 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-02 06:07:59.048
2025-07-02 06:07:59.056 ############################################################################
2025-07-02 06:07:59.062 ### L A U N C H W O R K E R U S I N G I S Q L, A S Y N C. ###
2025-07-02 06:07:59.068 ############################################################################
2025-07-02 06:07:59.076 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-02 06:07:59.086 '-user', act.db.user,
2025-07-02 06:07:59.096 '-password', act.db.password,
2025-07-02 06:07:59.104 '-pag', '999999',
2025-07-02 06:07:59.115 act.db.dsn
2025-07-02 06:07:59.122 ],
2025-07-02 06:07:59.135 stdout = hang_out,
2025-07-02 06:07:59.148 stderr = hang_err
2025-07-02 06:07:59.157 )
2025-07-02 06:07:59.163 # NB: when ISQL will establish attach, first record that it must lock is ID = 1 -- see above SQL_TO_BE_RESTARTED
2025-07-02 06:07:59.170 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-02 06:07:59.176 #
2025-07-02 06:07:59.182 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=1', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-02 06:07:59.189
2025-07-02 06:07:59.196
2025-07-02 06:07:59.203 #########################
2025-07-02 06:07:59.210 ### L O C K E R - 2 ###
2025-07-02 06:07:59.221 #########################
2025-07-02 06:07:59.232 con_lock_2.execute_immediate( f'insert /* LOCKER-2 */ into {target_obj}(id) values(110)' )
2025-07-02 06:07:59.240 con_lock_2.execute_immediate( f'insert /* LOCKER-2 */ into {target_obj}(id) values(-11)' )
2025-07-02 06:07:59.246 con_lock_2.commit()
2025-07-02 06:07:59.253 con_lock_2.execute_immediate( f'update /* LOCKER-2 */ {target_obj} set id=id where id = 110' )
2025-07-02 06:07:59.262 con_lock_2.execute_immediate( f'update /* LOCKER-2 */ {target_obj} set id=id where id = -11' )
2025-07-02 06:07:59.269
2025-07-02 06:07:59.276 #########################
2025-07-02 06:07:59.282 ### L O C K E R - 1 ###
2025-07-02 06:07:59.289 #########################
2025-07-02 06:07:59.299 con_lock_1.commit() # releases record with ID = 2 ==> now it can be locked by worker.
2025-07-02 06:07:59.308
2025-07-02 06:07:59.316 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 2.
2025-07-02 06:07:59.322 #
2025-07-02 06:07:59.328 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=2', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-02 06:07:59.340 # If we come here then it means that record with ID = 2 for sure is locked by WORKER.
2025-07-02 06:07:59.347
2025-07-02 06:07:59.352 con_lock_1.execute_immediate( f'insert /* LOCKER-1 */ into {target_obj}(id) values(120)' )
2025-07-02 06:07:59.356 con_lock_1.execute_immediate( f'insert /* LOCKER-1 */ into {target_obj}(id) values(-12)' )
2025-07-02 06:07:59.361 con_lock_1.commit()
2025-07-02 06:07:59.365 con_lock_1.execute_immediate( f'update /* LOCKER-1 */ {target_obj} set id=id where id = 120' )
2025-07-02 06:07:59.370 con_lock_1.execute_immediate( f'update /* LOCKER-1 */ {target_obj} set id=id where id = -12' )
2025-07-02 06:07:59.382
2025-07-02 06:07:59.392
2025-07-02 06:07:59.400 #########################
2025-07-02 06:07:59.408 ### L O C K E R - 2 ###
2025-07-02 06:07:59.415 #########################
2025-07-02 06:07:59.423 con_lock_2.commit() # releases TWO records with ID = -11 and 110.
2025-07-02 06:07:59.433
2025-07-02 06:07:59.442 # We have to WAIT HERE until worker will actually 'catch' just released records, in the order of its cursor: first with ID = -11, then with ID = 110.
2025-07-02 06:07:59.452 #
2025-07-02 06:07:59.460 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 110', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-02 06:07:59.469 # If we come here then it means that TWO records with ID = -11 and 110 for sure are locked by WORKER.
2025-07-02 06:07:59.476
2025-07-02 06:07:59.482
2025-07-02 06:07:59.490 con_lock_2.execute_immediate( f'insert into /* LOCKER-2 */ {target_obj}(id) values(130)' )
2025-07-02 06:07:59.496 con_lock_2.execute_immediate( f'insert into /* LOCKER-2 */ {target_obj}(id) values(-13)' )
2025-07-02 06:07:59.503 con_lock_2.commit()
2025-07-02 06:07:59.509 con_lock_2.execute_immediate( f'update /* LOCKER-2 */ {target_obj} set id=id where id = 130' )
2025-07-02 06:07:59.515 con_lock_2.execute_immediate( f'update /* LOCKER-2 */ {target_obj} set id=id where id = -13' )
2025-07-02 06:07:59.521
2025-07-02 06:07:59.527 #########################
2025-07-02 06:07:59.532 ### L O C K E R - 1 ###
2025-07-02 06:07:59.538 #########################
2025-07-02 06:07:59.544 con_lock_1.commit() # releases TWO records with ID = -12 and 120.
2025-07-02 06:07:59.550
2025-07-02 06:07:59.556 # We have to WAIT HERE until worker will actually 'catch' just released records, in the order of its cursor: first with ID = -12, then with ID = 120.
2025-07-02 06:07:59.562 #
2025-07-02 06:07:59.569 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 120', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-02 06:07:59.575 # If we come here then it means that TWO records with ID = -12 and 120 for sure are locked by WORKER.
2025-07-02 06:07:59.581
2025-07-02 06:07:59.587
2025-07-02 06:07:59.594 con_lock_1.execute_immediate( f'insert /* LOCKER-1 */ into {target_obj}(id) values(140)' )
2025-07-02 06:07:59.600 con_lock_1.execute_immediate( f'insert /* LOCKER-1 */ into {target_obj}(id) values(-14)' )
2025-07-02 06:07:59.607 con_lock_1.commit()
2025-07-02 06:07:59.614 con_lock_1.execute_immediate( f'update /* LOCKER-1 */ {target_obj} set id=id where id = 140' )
2025-07-02 06:07:59.620 con_lock_1.execute_immediate( f'update /* LOCKER-1 */ {target_obj} set id=id where id = -14' )
2025-07-02 06:07:59.626
2025-07-02 06:07:59.632 #########################
2025-07-02 06:07:59.638 ### L O C K E R - 2 ###
2025-07-02 06:07:59.644 #########################
2025-07-02 06:07:59.650 con_lock_2.commit()
2025-07-02 06:07:59.663
2025-07-02 06:07:59.674 # We have to WAIT HERE until worker will actually 'catch' just released records, in the order of its cursor: first with ID = -13, then with ID = 130.
2025-07-02 06:07:59.683 #
2025-07-02 06:07:59.691 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 130', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-02 06:07:59.700 # If we come here then it means that TWO records with ID = -13 and 130 for sure are locked by WORKER.
2025-07-02 06:07:59.707
2025-07-02 06:07:59.713 #########################
2025-07-02 06:07:59.719 ### L O C K E R - 1 ###
2025-07-02 06:07:59.728 #########################
2025-07-02 06:07:59.739 con_lock_1.commit() # WORKER will complete his job after this
2025-07-02 06:07:59.752
2025-07-02 06:07:59.761
2025-07-02 06:07:59.770 # Here we wait for ISQL complete its mission:
2025-07-02 06:07:59.777 p_worker.wait()
2025-07-02 06:07:59.784
2025-07-02 06:07:59.793 #< with act.db.connect()
2025-07-02 06:07:59.804
2025-07-02 06:07:59.815 for g in (fn_worker_log, fn_worker_err):
2025-07-02 06:07:59.824 with g.open() as f:
2025-07-02 06:07:59.838 for line in f:
2025-07-02 06:07:59.849 if line.split():
2025-07-02 06:07:59.862 if g == fn_worker_log:
2025-07-02 06:07:59.873 print(f'checked_mode: {checked_mode}, STDLOG: {line}')
2025-07-02 06:07:59.881 else:
2025-07-02 06:07:59.888 print(f'UNEXPECTED STDERR {line}')
2025-07-02 06:07:59.895
2025-07-02 06:07:59.901 expected_stdout_worker = f"""
2025-07-02 06:07:59.915 checked_mode: {checked_mode}, STDLOG: Records affected: 10
2025-07-02 06:07:59.924 checked_mode: {checked_mode}, STDLOG: ID
2025-07-02 06:07:59.931 checked_mode: {checked_mode}, STDLOG:
2025-07-02 06:07:59.938 checked_mode: {checked_mode}, STDLOG: -140
2025-07-02 06:07:59.946 checked_mode: {checked_mode}, STDLOG: -130
2025-07-02 06:07:59.952 checked_mode: {checked_mode}, STDLOG: -120
2025-07-02 06:07:59.957 checked_mode: {checked_mode}, STDLOG: -110
2025-07-02 06:07:59.963 checked_mode: {checked_mode}, STDLOG: -2
2025-07-02 06:07:59.968 checked_mode: {checked_mode}, STDLOG: -1
2025-07-02 06:07:59.973 checked_mode: {checked_mode}, STDLOG: 11
2025-07-02 06:07:59.978 checked_mode: {checked_mode}, STDLOG: 12
2025-07-02 06:07:59.983 checked_mode: {checked_mode}, STDLOG: 13
2025-07-02 06:07:59.989 checked_mode: {checked_mode}, STDLOG: 14
2025-07-02 06:07:59.995 checked_mode: {checked_mode}, STDLOG: Records affected: 10
2025-07-02 06:08:00.003 checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-02 06:08:00.009 checked_mode: {checked_mode}, STDLOG:
2025-07-02 06:08:00.013 checked_mode: {checked_mode}, STDLOG: 1 UPD 1
2025-07-02 06:08:00.019 checked_mode: {checked_mode}, STDLOG: -14 UPD 2
2025-07-02 06:08:00.026 checked_mode: {checked_mode}, STDLOG: -13 UPD 2
2025-07-02 06:08:00.033 checked_mode: {checked_mode}, STDLOG: -12 UPD 2
2025-07-02 06:08:00.040 checked_mode: {checked_mode}, STDLOG: -11 UPD 2
2025-07-02 06:08:00.046 checked_mode: {checked_mode}, STDLOG: 1 UPD 2
2025-07-02 06:08:00.052 checked_mode: {checked_mode}, STDLOG: 2 UPD 2
2025-07-02 06:08:00.058 checked_mode: {checked_mode}, STDLOG: 110 UPD 2
2025-07-02 06:08:00.064 checked_mode: {checked_mode}, STDLOG: 120 UPD 2
2025-07-02 06:08:00.070 checked_mode: {checked_mode}, STDLOG: 130 UPD 2
2025-07-02 06:08:00.079 checked_mode: {checked_mode}, STDLOG: 140 UPD 2
2025-07-02 06:08:00.091 checked_mode: {checked_mode}, STDLOG: Records affected: 11
2025-07-02 06:08:00.099 """
2025-07-02 06:08:00.106
2025-07-02 06:08:00.112 act.expected_stdout = expected_stdout_worker
2025-07-02 06:08:00.119 act.stdout = capsys.readouterr().out
2025-07-02 06:08:00.125 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-02 06:08:00.139 E assert
2025-07-02 06:08:00.148 E checked_mode: table, STDLOG: Records affected: 10
2025-07-02 06:08:00.156 E checked_mode: table, STDLOG: ID
2025-07-02 06:08:00.163 E checked_mode: table, STDLOG:
2025-07-02 06:08:00.171 E checked_mode: table, STDLOG: -140
2025-07-02 06:08:00.182 E checked_mode: table, STDLOG: -130
2025-07-02 06:08:00.191 E checked_mode: table, STDLOG: -120
2025-07-02 06:08:00.199 E checked_mode: table, STDLOG: -110
2025-07-02 06:08:00.207 E checked_mode: table, STDLOG: -2
2025-07-02 06:08:00.219 E checked_mode: table, STDLOG: -1
2025-07-02 06:08:00.229 E checked_mode: table, STDLOG: 11
2025-07-02 06:08:00.237 E checked_mode: table, STDLOG: 12
2025-07-02 06:08:00.244 E checked_mode: table, STDLOG: 13
2025-07-02 06:08:00.251 E checked_mode: table, STDLOG: 14
2025-07-02 06:08:00.258 E checked_mode: table, STDLOG: Records affected: 10
2025-07-02 06:08:00.268 E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-02 06:08:00.281 E checked_mode: table, STDLOG:
2025-07-02 06:08:00.291 E - checked_mode: table, STDLOG: 1 UPD 1
2025-07-02 06:08:00.309 E + checked_mode: table, STDLOG: 1UPD 1
2025-07-02 06:08:00.315 E - checked_mode: table, STDLOG: -14 UPD 2
2025-07-02 06:08:00.328 E + checked_mode: table, STDLOG: -14UPD 2
2025-07-02 06:08:00.334 E - checked_mode: table, STDLOG: -13 UPD 2
2025-07-02 06:08:00.346 E + checked_mode: table, STDLOG: -13UPD 2
2025-07-02 06:08:00.353 E - checked_mode: table, STDLOG: -12 UPD 2
2025-07-02 06:08:00.368 E + checked_mode: table, STDLOG: -12UPD 2
2025-07-02 06:08:00.373 E - checked_mode: table, STDLOG: -11 UPD 2
2025-07-02 06:08:00.382 E + checked_mode: table, STDLOG: -11UPD 2
2025-07-02 06:08:00.387 E - checked_mode: table, STDLOG: 1 UPD 2
2025-07-02 06:08:00.396 E + checked_mode: table, STDLOG: 1UPD 2
2025-07-02 06:08:00.401 E - checked_mode: table, STDLOG: 2 UPD 2
2025-07-02 06:08:00.411 E + checked_mode: table, STDLOG: 2UPD 2
2025-07-02 06:08:00.416 E - checked_mode: table, STDLOG: 110 UPD 2
2025-07-02 06:08:00.427 E + checked_mode: table, STDLOG: 110UPD 2
2025-07-02 06:08:00.433 E - checked_mode: table, STDLOG: 120 UPD 2
2025-07-02 06:08:00.447 E + checked_mode: table, STDLOG: 120UPD 2
2025-07-02 06:08:00.454 E - checked_mode: table, STDLOG: 130 UPD 2
2025-07-02 06:08:00.466 E + checked_mode: table, STDLOG: 130UPD 2
2025-07-02 06:08:00.473 E - checked_mode: table, STDLOG: 140 UPD 2
2025-07-02 06:08:00.485 E + checked_mode: table, STDLOG: 140UPD 2
2025-07-02 06:08:00.492 E checked_mode: table, STDLOG: Records affected: 11
2025-07-02 06:08:00.498
2025-07-02 06:08:00.505 tests/functional/transactions/test_read_consist_sttm_restart_on_update_03.py:480: AssertionError
2025-07-02 06:08:00.511 ---------------------------- Captured stdout setup -----------------------------
2025-07-02 06:08:00.518 Creating db: localhost:/var/tmp/qa_2024/test_12487/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_12487/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12487/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12487/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 ROWS 10"
# add rows with ID = 1, 2:
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 2;
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 /* LOCKER-1 */ {target_obj} set id=id where id = 2' )
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;
-- WORKER. THIS MUST BE LOCKED NOW BY LOCKER_i:
{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 ###
#########################
con_lock_2.execute_immediate( f'insert /* LOCKER-2 */ into {target_obj}(id) values(110)' )
con_lock_2.execute_immediate( f'insert /* LOCKER-2 */ into {target_obj}(id) values(-11)' )
con_lock_2.commit()
con_lock_2.execute_immediate( f'update /* LOCKER-2 */ {target_obj} set id=id where id = 110' )
con_lock_2.execute_immediate( f'update /* LOCKER-2 */ {target_obj} set id=id where id = -11' )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # releases record with ID = 2 ==> now it can be locked by worker.
# We have to WAIT HERE until worker will actually 'catch' just released record with ID = 2.
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=2', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = 2 for sure is locked by WORKER.
con_lock_1.execute_immediate( f'insert /* LOCKER-1 */ into {target_obj}(id) values(120)' )
con_lock_1.execute_immediate( f'insert /* LOCKER-1 */ into {target_obj}(id) values(-12)' )
con_lock_1.commit()
con_lock_1.execute_immediate( f'update /* LOCKER-1 */ {target_obj} set id=id where id = 120' )
con_lock_1.execute_immediate( f'update /* LOCKER-1 */ {target_obj} set id=id where id = -12' )
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.commit() # releases TWO records with ID = -11 and 110.
# We have to WAIT HERE until worker will actually 'catch' just released records, in the order of its cursor: first with ID = -11, then with ID = 110.
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 110', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that TWO records with ID = -11 and 110 for sure are locked by WORKER.
con_lock_2.execute_immediate( f'insert into /* LOCKER-2 */ {target_obj}(id) values(130)' )
con_lock_2.execute_immediate( f'insert into /* LOCKER-2 */ {target_obj}(id) values(-13)' )
con_lock_2.commit()
con_lock_2.execute_immediate( f'update /* LOCKER-2 */ {target_obj} set id=id where id = 130' )
con_lock_2.execute_immediate( f'update /* LOCKER-2 */ {target_obj} set id=id where id = -13' )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # releases TWO records with ID = -12 and 120.
# We have to WAIT HERE until worker will actually 'catch' just released records, in the order of its cursor: first with ID = -12, then with ID = 120.
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 120', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that TWO records with ID = -12 and 120 for sure are locked by WORKER.
con_lock_1.execute_immediate( f'insert /* LOCKER-1 */ into {target_obj}(id) values(140)' )
con_lock_1.execute_immediate( f'insert /* LOCKER-1 */ into {target_obj}(id) values(-14)' )
con_lock_1.commit()
con_lock_1.execute_immediate( f'update /* LOCKER-1 */ {target_obj} set id=id where id = 140' )
con_lock_1.execute_immediate( f'update /* LOCKER-1 */ {target_obj} set id=id where id = -14' )
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.commit()
# We have to WAIT HERE until worker will actually 'catch' just released records, in the order of its cursor: first with ID = -13, then with ID = 130.
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 130', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that TWO records with ID = -13 and 130 for sure are locked by WORKER.
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.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: 10
checked_mode: {checked_mode}, STDLOG: ID
checked_mode: {checked_mode}, STDLOG:
checked_mode: {checked_mode}, STDLOG: -140
checked_mode: {checked_mode}, STDLOG: -130
checked_mode: {checked_mode}, STDLOG: -120
checked_mode: {checked_mode}, STDLOG: -110
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: 14
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: 1 UPD 1
checked_mode: {checked_mode}, STDLOG: -14 UPD 2
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: 110 UPD 2
checked_mode: {checked_mode}, STDLOG: 120 UPD 2
checked_mode: {checked_mode}, STDLOG: 130 UPD 2
checked_mode: {checked_mode}, STDLOG: 140 UPD 2
checked_mode: {checked_mode}, STDLOG: Records affected: 11
"""
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: 10
E checked_mode: table, STDLOG: ID
E checked_mode: table, STDLOG:
E checked_mode: table, STDLOG: -140
E checked_mode: table, STDLOG: -130
E checked_mode: table, STDLOG: -120
E checked_mode: table, STDLOG: -110
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: 14
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: 1 UPD 1
E + checked_mode: table, STDLOG: 1UPD 1
E - checked_mode: table, STDLOG: -14 UPD 2
E + checked_mode: table, STDLOG: -14UPD 2
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: 110 UPD 2
E + checked_mode: table, STDLOG: 110UPD 2
E - checked_mode: table, STDLOG: 120 UPD 2
E + checked_mode: table, STDLOG: 120UPD 2
E - checked_mode: table, STDLOG: 130 UPD 2
E + checked_mode: table, STDLOG: 130UPD 2
E - checked_mode: table, STDLOG: 140 UPD 2
E + checked_mode: table, STDLOG: 140UPD 2
E checked_mode: table, STDLOG: Records affected: 11
tests/functional/transactions/test_read_consist_sttm_restart_on_update_03.py:480: AssertionError
|