2 @message |
assert
checked_mode: table, STDLOG: Records affected: 9
checked_mode: table, STDLOG: ID
checked_mode: table, STDLOG:
checked_mode: table, STDLOG: -14
checked_mode: table, STDLOG: -13
checked_mode: table, STDLOG: -12
checked_mode: table, STDLOG: -11
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: Records affected: 9
checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: table, STDLOG:
- checked_mode: table, STDLOG: 5 UPD 1
+ checked_mode: table, STDLOG: 5UPD 1
- checked_mode: table, STDLOG: 4 UPD 1
+ checked_mode: table, STDLOG: 4UPD 1
- checked_mode: table, STDLOG: 3 UPD 1
+ checked_mode: table, STDLOG: 3UPD 1
- checked_mode: table, STDLOG: 2 UPD 1
+ checked_mode: table, STDLOG: 2UPD 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: 5 UPD 2
+ checked_mode: table, STDLOG: 5UPD 2
- checked_mode: table, STDLOG: 4 UPD 2
+ checked_mode: table, STDLOG: 4UPD 2
- checked_mode: table, STDLOG: 3 UPD 2
+ checked_mode: table, STDLOG: 3UPD 2
- 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: Records affected: 13
LOG DETAILS:
2025-07-01 06:05:09.023
2025-07-01 06:05:09.029 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-01 06:05:09.036 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12485/tmp_worker.sql')
2025-07-01 06:05:09.044 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12485/tmp_worker.log')
2025-07-01 06:05:09.051 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12485/tmp_worker.err')
2025-07-01 06:05:09.058 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-01 06:05:09.068
2025-07-01 06:05:09.079 @pytest.mark.trace
2025-07-01 06:05:09.086 @pytest.mark.version('>=4.0')
2025-07-01 06:05:09.093 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-01 06:05:09.099 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-01 06:05:09.107
2025-07-01 06:05:09.118 for checked_mode in('table', 'view'):
2025-07-01 06:05:09.125 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-01 06:05:09.132
2025-07-01 06:05:09.139 # SQL_TO_BE_RESTARTED = f"update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = -id order by id DESC"
2025-07-01 06:05:09.147 SQL_TO_BE_RESTARTED = f"update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = -id where exists(select * from {target_obj} where id > 0) order by id DESC"
2025-07-01 06:05:09.154
2025-07-01 06:05:09.163 # add rows with ID = 1, 2, ..., 5:
2025-07-01 06:05:09.175 sql_addi = f'''
2025-07-01 06:05:09.184 set term ^;
2025-07-01 06:05:09.195 execute block as
2025-07-01 06:05:09.204 begin
2025-07-01 06:05:09.212 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-01 06:05:09.217 end
2025-07-01 06:05:09.222 ^
2025-07-01 06:05:09.228 set term ;^
2025-07-01 06:05:09.234 insert into {target_obj}(id, x) select row_number()over(),row_number()over() from rdb$types rows 5;
2025-07-01 06:05:09.240 commit;
2025-07-01 06:05:09.246 '''
2025-07-01 06:05:09.253
2025-07-01 06:05:09.259 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-07-01 06:05:09.267 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-01 06:05:09.275 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-01 06:05:09.282 assert act.stderr == ''
2025-07-01 06:05:09.289 act.reset()
2025-07-01 06:05:09.296
2025-07-01 06:05:09.303 trace_cfg_items = [
2025-07-01 06:05:09.311 'time_threshold = 0',
2025-07-01 06:05:09.318 'log_errors = true',
2025-07-01 06:05:09.330 'log_statement_start = true',
2025-07-01 06:05:09.340 'log_statement_finish = true',
2025-07-01 06:05:09.353 ]
2025-07-01 06:05:09.362
2025-07-01 06:05:09.370 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-01 06:05:09.376
2025-07-01 06:05:09.390 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:09.403
2025-07-01 06:05:09.413 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-01 06:05:09.419 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-01 06:05:09.426 cur_monitoring = tx_monitoring.cursor()
2025-07-01 06:05:09.439
2025-07-01 06:05:09.449 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-01 06:05:09.458 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-01 06:05:09.465 c.execute_immediate(sttm)
2025-07-01 06:05:09.471
2025-07-01 06:05:09.477 #########################
2025-07-01 06:05:09.489 ### L O C K E R - 1 ###
2025-07-01 06:05:09.497 #########################
2025-07-01 06:05:09.502
2025-07-01 06:05:09.508 con_lock_1.execute_immediate( f'update {target_obj} set id = id where id = 1' )
2025-07-01 06:05:09.517
2025-07-01 06:05:09.529 worker_sql = f'''
2025-07-01 06:05:09.538 set list on;
2025-07-01 06:05:09.547 set autoddl off;
2025-07-01 06:05:09.555 set term ^;
2025-07-01 06:05:09.567 execute block returns (whoami varchar(30)) as
2025-07-01 06:05:09.577 begin
2025-07-01 06:05:09.587 whoami = 'WORKER'; -- , ATT#' || current_connection;
2025-07-01 06:05:09.596 rdb$set_context('USER_SESSION','WHO', whoami);
2025-07-01 06:05:09.602 -- suspend;
2025-07-01 06:05:09.616 end
2025-07-01 06:05:09.625 ^
2025-07-01 06:05:09.635 set term ;^
2025-07-01 06:05:09.647 commit;
2025-07-01 06:05:09.658
2025-07-01 06:05:09.668 SET KEEP_TRAN_PARAMS ON;
2025-07-01 06:05:09.679 set transaction read committed read consistency;
2025-07-01 06:05:09.690 set list off;
2025-07-01 06:05:09.702 set wng off;
2025-07-01 06:05:09.715 set count on;
2025-07-01 06:05:09.727
2025-07-01 06:05:09.736 -- THIS MUST BE LOCKED
2025-07-01 06:05:09.745 {SQL_TO_BE_RESTARTED};
2025-07-01 06:05:09.752
2025-07-01 06:05:09.758 -- check results:
2025-07-01 06:05:09.764 -- ###############
2025-07-01 06:05:09.776 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:09.787
2025-07-01 06:05:09.796 select v.old_id, v.op, v.snap_no_rank from v_worker_log v where v.op = 'upd';
2025-07-01 06:05:09.803
2025-07-01 06:05:09.810 set width who 10;
2025-07-01 06:05:09.819 -- DO NOT check this! Values can differ here from one run to another!
2025-07-01 06:05:09.829 -- 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:09.841
2025-07-01 06:05:09.851 rollback;
2025-07-01 06:05:09.861
2025-07-01 06:05:09.869 '''
2025-07-01 06:05:09.875
2025-07-01 06:05:09.882 fn_worker_sql.write_text(worker_sql)
2025-07-01 06:05:09.890
2025-07-01 06:05:09.899 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-01 06:05:09.907
2025-07-01 06:05:09.913 ############################################################################
2025-07-01 06:05:09.919 ### 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:09.924 ############################################################################
2025-07-01 06:05:09.929 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-01 06:05:09.935 '-user', act.db.user,
2025-07-01 06:05:09.940 '-password', act.db.password,
2025-07-01 06:05:09.945 '-pag', '999999',
2025-07-01 06:05:09.950 act.db.dsn
2025-07-01 06:05:09.956 ],
2025-07-01 06:05:09.962 stdout = hang_out,
2025-07-01 06:05:09.968 stderr = hang_err
2025-07-01 06:05:09.974 )
2025-07-01 06:05:09.985 # 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:05:09.994 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:05:10.002 #
2025-07-01 06:05:10.017 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:10.026
2025-07-01 06:05:10.033 #########################
2025-07-01 06:05:10.039 ### L O C K E R - 2 ###
2025-07-01 06:05:10.045 #########################
2025-07-01 06:05:10.051 con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(11)' )
2025-07-01 06:05:10.056 con_lock_2.commit()
2025-07-01 06:05:10.062 con_lock_2.execute_immediate( f'update {target_obj} set id = id where id = 11' )
2025-07-01 06:05:10.073
2025-07-01 06:05:10.083 #########################
2025-07-01 06:05:10.090 ### L O C K E R - 1 ###
2025-07-01 06:05:10.097 #########################
2025-07-01 06:05:10.105 con_lock_1.commit() # releases record with ID = 1 ==> now it can be locked by worker.
2025-07-01 06:05:10.111
2025-07-01 06:05:10.116
2025-07-01 06:05:10.126 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 1.
2025-07-01 06:05:10.138 #
2025-07-01 06:05:10.148 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:10.157 # If we come here then it means that record with ID = 1 for sure is locked by WORKER.
2025-07-01 06:05:10.165
2025-07-01 06:05:10.171
2025-07-01 06:05:10.178 con_lock_1.execute_immediate( f'insert into {target_obj}(id) values(12)' )
2025-07-01 06:05:10.184 con_lock_1.commit()
2025-07-01 06:05:10.190 con_lock_1.execute_immediate( f'update {target_obj} set id = id where id = 12' )
2025-07-01 06:05:10.201
2025-07-01 06:05:10.211
2025-07-01 06:05:10.218 #########################
2025-07-01 06:05:10.227 ### L O C K E R - 2 ###
2025-07-01 06:05:10.236 #########################
2025-07-01 06:05:10.245 con_lock_2.commit() # releases record with ID = 11 ==> now it can be locked by worker.
2025-07-01 06:05:10.252
2025-07-01 06:05:10.258 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 11.
2025-07-01 06:05:10.263 #
2025-07-01 06:05:10.271 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:10.278 # If we come here then it means that record with ID = 11 for sure is locked by WORKER.
2025-07-01 06:05:10.284
2025-07-01 06:05:10.290
2025-07-01 06:05:10.296 con_lock_2.execute_immediate( f'insert into {target_obj}(id) values(13)' )
2025-07-01 06:05:10.302 con_lock_2.commit()
2025-07-01 06:05:10.313 con_lock_2.execute_immediate( f'update {target_obj} set id = id where id = 13' )
2025-07-01 06:05:10.322
2025-07-01 06:05:10.329 #########################
2025-07-01 06:05:10.336 ### L O C K E R - 1 ###
2025-07-01 06:05:10.342 #########################
2025-07-01 06:05:10.349 con_lock_1.commit() # releases record with ID = 12 ==> now it can be locked by worker.
2025-07-01 06:05:10.354
2025-07-01 06:05:10.358 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 12.
2025-07-01 06:05:10.365 #
2025-07-01 06:05:10.371 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:10.378 # If we come here then it means that record with ID = 12 for sure is locked by WORKER.
2025-07-01 06:05:10.383
2025-07-01 06:05:10.395 con_lock_1.execute_immediate( f'insert into {target_obj}(id) values(14)' )
2025-07-01 06:05:10.403 con_lock_1.commit()
2025-07-01 06:05:10.409 con_lock_1.execute_immediate( f'update {target_obj} set id = id where id = 14' )
2025-07-01 06:05:10.415
2025-07-01 06:05:10.422 #########################
2025-07-01 06:05:10.436 ### L O C K E R - 2 ###
2025-07-01 06:05:10.450 #########################
2025-07-01 06:05:10.463 con_lock_2.commit()
2025-07-01 06:05:10.476
2025-07-01 06:05:10.487 # We have to WAIT HERE until worker will actually 'catch' just released record with ID = 13.
2025-07-01 06:05:10.496 #
2025-07-01 06:05:10.502 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=13', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:05:10.507 # If we come here then it means that record with ID = 13 for sure is locked by WORKER.
2025-07-01 06:05:10.513
2025-07-01 06:05:10.518 #########################
2025-07-01 06:05:10.523 ### L O C K E R - 1 ###
2025-07-01 06:05:10.528 #########################
2025-07-01 06:05:10.533 con_lock_1.commit() # WORKER will complete his job after this
2025-07-01 06:05:10.538
2025-07-01 06:05:10.543
2025-07-01 06:05:10.548 # Here we wait for ISQL complete its mission:
2025-07-01 06:05:10.553 p_worker.wait()
2025-07-01 06:05:10.563
2025-07-01 06:05:10.572 #< with act.db.connect()
2025-07-01 06:05:10.581
2025-07-01 06:05:10.587 for g in (fn_worker_log, fn_worker_err):
2025-07-01 06:05:10.595 with g.open() as f:
2025-07-01 06:05:10.603 for line in f:
2025-07-01 06:05:10.613 if line.split():
2025-07-01 06:05:10.622 if g == fn_worker_log:
2025-07-01 06:05:10.630 print(f'checked_mode: {checked_mode}, STDLOG: {line}')
2025-07-01 06:05:10.636 else:
2025-07-01 06:05:10.641 print(f'UNEXPECTED STDERR {line}')
2025-07-01 06:05:10.647
2025-07-01 06:05:10.653 expected_stdout_worker = f"""
2025-07-01 06:05:10.660 checked_mode: {checked_mode}, STDLOG: Records affected: 9
2025-07-01 06:05:10.666
2025-07-01 06:05:10.672 checked_mode: {checked_mode}, STDLOG: ID
2025-07-01 06:05:10.679 checked_mode: {checked_mode}, STDLOG: =======
2025-07-01 06:05:10.686 checked_mode: {checked_mode}, STDLOG: -14
2025-07-01 06:05:10.696 checked_mode: {checked_mode}, STDLOG: -13
2025-07-01 06:05:10.705 checked_mode: {checked_mode}, STDLOG: -12
2025-07-01 06:05:10.712 checked_mode: {checked_mode}, STDLOG: -11
2025-07-01 06:05:10.722 checked_mode: {checked_mode}, STDLOG: -5
2025-07-01 06:05:10.733 checked_mode: {checked_mode}, STDLOG: -4
2025-07-01 06:05:10.743 checked_mode: {checked_mode}, STDLOG: -3
2025-07-01 06:05:10.756 checked_mode: {checked_mode}, STDLOG: -2
2025-07-01 06:05:10.770 checked_mode: {checked_mode}, STDLOG: -1
2025-07-01 06:05:10.784 checked_mode: {checked_mode}, STDLOG: Records affected: 9
2025-07-01 06:05:10.796
2025-07-01 06:05:10.805 checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:05:10.815 checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
2025-07-01 06:05:10.826 checked_mode: {checked_mode}, STDLOG: 5 UPD 1
2025-07-01 06:05:10.835 checked_mode: {checked_mode}, STDLOG: 4 UPD 1
2025-07-01 06:05:10.843 checked_mode: {checked_mode}, STDLOG: 3 UPD 1
2025-07-01 06:05:10.850 checked_mode: {checked_mode}, STDLOG: 2 UPD 1
2025-07-01 06:05:10.858 checked_mode: {checked_mode}, STDLOG: 14 UPD 2
2025-07-01 06:05:10.865 checked_mode: {checked_mode}, STDLOG: 13 UPD 2
2025-07-01 06:05:10.872 checked_mode: {checked_mode}, STDLOG: 12 UPD 2
2025-07-01 06:05:10.879 checked_mode: {checked_mode}, STDLOG: 11 UPD 2
2025-07-01 06:05:10.887 checked_mode: {checked_mode}, STDLOG: 5 UPD 2
2025-07-01 06:05:10.895 checked_mode: {checked_mode}, STDLOG: 4 UPD 2
2025-07-01 06:05:10.908 checked_mode: {checked_mode}, STDLOG: 3 UPD 2
2025-07-01 06:05:10.916 checked_mode: {checked_mode}, STDLOG: 2 UPD 2
2025-07-01 06:05:10.928 checked_mode: {checked_mode}, STDLOG: 1 UPD 2
2025-07-01 06:05:10.938
2025-07-01 06:05:10.947 checked_mode: {checked_mode}, STDLOG: Records affected: 13
2025-07-01 06:05:10.954 """
2025-07-01 06:05:10.961
2025-07-01 06:05:10.966 act.expected_stdout = expected_stdout_worker
2025-07-01 06:05:10.971 act.stdout = capsys.readouterr().out
2025-07-01 06:05:10.976 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-01 06:05:10.981 E assert
2025-07-01 06:05:10.987 E checked_mode: table, STDLOG: Records affected: 9
2025-07-01 06:05:10.992 E checked_mode: table, STDLOG: ID
2025-07-01 06:05:10.997 E checked_mode: table, STDLOG:
2025-07-01 06:05:11.005 E checked_mode: table, STDLOG: -14
2025-07-01 06:05:11.015 E checked_mode: table, STDLOG: -13
2025-07-01 06:05:11.023 E checked_mode: table, STDLOG: -12
2025-07-01 06:05:11.031 E checked_mode: table, STDLOG: -11
2025-07-01 06:05:11.038 E checked_mode: table, STDLOG: -5
2025-07-01 06:05:11.046 E checked_mode: table, STDLOG: -4
2025-07-01 06:05:11.055 E checked_mode: table, STDLOG: -3
2025-07-01 06:05:11.065 E checked_mode: table, STDLOG: -2
2025-07-01 06:05:11.072 E checked_mode: table, STDLOG: -1
2025-07-01 06:05:11.078 E checked_mode: table, STDLOG: Records affected: 9
2025-07-01 06:05:11.087 E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:05:11.096 E checked_mode: table, STDLOG:
2025-07-01 06:05:11.103 E - checked_mode: table, STDLOG: 5 UPD 1
2025-07-01 06:05:11.115 E + checked_mode: table, STDLOG: 5UPD 1
2025-07-01 06:05:11.121 E - checked_mode: table, STDLOG: 4 UPD 1
2025-07-01 06:05:11.136 E + checked_mode: table, STDLOG: 4UPD 1
2025-07-01 06:05:11.150 E - checked_mode: table, STDLOG: 3 UPD 1
2025-07-01 06:05:11.167 E + checked_mode: table, STDLOG: 3UPD 1
2025-07-01 06:05:11.174 E - checked_mode: table, STDLOG: 2 UPD 1
2025-07-01 06:05:11.185 E + checked_mode: table, STDLOG: 2UPD 1
2025-07-01 06:05:11.190 E - checked_mode: table, STDLOG: 14 UPD 2
2025-07-01 06:05:11.199 E + checked_mode: table, STDLOG: 14UPD 2
2025-07-01 06:05:11.204 E - checked_mode: table, STDLOG: 13 UPD 2
2025-07-01 06:05:11.213 E + checked_mode: table, STDLOG: 13UPD 2
2025-07-01 06:05:11.218 E - checked_mode: table, STDLOG: 12 UPD 2
2025-07-01 06:05:11.227 E + checked_mode: table, STDLOG: 12UPD 2
2025-07-01 06:05:11.231 E - checked_mode: table, STDLOG: 11 UPD 2
2025-07-01 06:05:11.240 E + checked_mode: table, STDLOG: 11UPD 2
2025-07-01 06:05:11.245 E - checked_mode: table, STDLOG: 5 UPD 2
2025-07-01 06:05:11.255 E + checked_mode: table, STDLOG: 5UPD 2
2025-07-01 06:05:11.260 E - checked_mode: table, STDLOG: 4 UPD 2
2025-07-01 06:05:11.269 E + checked_mode: table, STDLOG: 4UPD 2
2025-07-01 06:05:11.274 E - checked_mode: table, STDLOG: 3 UPD 2
2025-07-01 06:05:11.283 E + checked_mode: table, STDLOG: 3UPD 2
2025-07-01 06:05:11.287 E - checked_mode: table, STDLOG: 2 UPD 2
2025-07-01 06:05:11.296 E + checked_mode: table, STDLOG: 2UPD 2
2025-07-01 06:05:11.301 E - checked_mode: table, STDLOG: 1 UPD 2
2025-07-01 06:05:11.310 E + checked_mode: table, STDLOG: 1UPD 2
2025-07-01 06:05:11.315 E checked_mode: table, STDLOG: Records affected: 13
2025-07-01 06:05:11.319
2025-07-01 06:05:11.324 tests/functional/transactions/test_read_consist_sttm_restart_on_update_02.py:457: AssertionError
2025-07-01 06:05:11.328 ---------------------------- Captured stdout setup -----------------------------
2025-07-01 06:05:11.333 Creating db: localhost:/var/tmp/qa_2024/test_12485/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_12485/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12485/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12485/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 order by id DESC"
SQL_TO_BE_RESTARTED = f"update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = -id where exists(select * from {target_obj} where id > 0) order by id DESC"
# 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 = 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 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 = 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 ###
#########################
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 = 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.
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.
con_lock_1.execute_immediate( f'insert into {target_obj}(id) values(14)' )
con_lock_1.commit()
con_lock_1.execute_immediate( f'update {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 record with ID = 13.
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=13', SQL_TAG_THAT_WE_WAITING_FOR)
# If we come here then it means that record with ID = 13 for sure is 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: 9
checked_mode: {checked_mode}, STDLOG: ID
checked_mode: {checked_mode}, STDLOG: =======
checked_mode: {checked_mode}, STDLOG: -14
checked_mode: {checked_mode}, STDLOG: -13
checked_mode: {checked_mode}, STDLOG: -12
checked_mode: {checked_mode}, STDLOG: -11
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: Records affected: 9
checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, STDLOG: 5 UPD 1
checked_mode: {checked_mode}, STDLOG: 4 UPD 1
checked_mode: {checked_mode}, STDLOG: 3 UPD 1
checked_mode: {checked_mode}, STDLOG: 2 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: 5 UPD 2
checked_mode: {checked_mode}, STDLOG: 4 UPD 2
checked_mode: {checked_mode}, STDLOG: 3 UPD 2
checked_mode: {checked_mode}, STDLOG: 2 UPD 2
checked_mode: {checked_mode}, STDLOG: 1 UPD 2
checked_mode: {checked_mode}, STDLOG: Records affected: 13
"""
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: 9
E checked_mode: table, STDLOG: ID
E checked_mode: table, STDLOG:
E checked_mode: table, STDLOG: -14
E checked_mode: table, STDLOG: -13
E checked_mode: table, STDLOG: -12
E checked_mode: table, STDLOG: -11
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: Records affected: 9
E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
E checked_mode: table, STDLOG:
E - checked_mode: table, STDLOG: 5 UPD 1
E + checked_mode: table, STDLOG: 5UPD 1
E - checked_mode: table, STDLOG: 4 UPD 1
E + checked_mode: table, STDLOG: 4UPD 1
E - checked_mode: table, STDLOG: 3 UPD 1
E + checked_mode: table, STDLOG: 3UPD 1
E - checked_mode: table, STDLOG: 2 UPD 1
E + checked_mode: table, STDLOG: 2UPD 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: 5 UPD 2
E + checked_mode: table, STDLOG: 5UPD 2
E - checked_mode: table, STDLOG: 4 UPD 2
E + checked_mode: table, STDLOG: 4UPD 2
E - checked_mode: table, STDLOG: 3 UPD 2
E + checked_mode: table, STDLOG: 3UPD 2
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: Records affected: 13
tests/functional/transactions/test_read_consist_sttm_restart_on_update_02.py:457: AssertionError
|