2 @message |
assert
checked_mode: table, STDLOG: Records affected: 2
checked_mode: table, STDLOG: ID X
checked_mode: table, STDLOG:
checked_mode: table, STDLOG: -5 5
checked_mode: table, STDLOG: -4 4
checked_mode: table, STDLOG: -3 3
checked_mode: table, STDLOG: -2 2
checked_mode: table, STDLOG: -1 1
checked_mode: table, STDLOG: 0 0
checked_mode: table, STDLOG: 1 1
checked_mode: table, STDLOG: Records affected: 7
checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: table, STDLOG:
- checked_mode: table, STDLOG: 0 UPD 1
+ checked_mode: table, STDLOG: 0UPD 1
- checked_mode: table, STDLOG: 1 UPD 1
+ checked_mode: table, STDLOG: 1UPD 1
- checked_mode: table, STDLOG: 0 UPD 2
+ checked_mode: table, STDLOG: 0UPD 2
- checked_mode: table, STDLOG: 1 UPD 2
+ checked_mode: table, STDLOG: 1UPD 2
- checked_mode: table, STDLOG: 0 UPD 3
+ checked_mode: table, STDLOG: 0UPD 3
- checked_mode: table, STDLOG: 1 UPD 3
+ checked_mode: table, STDLOG: 1UPD 3
- checked_mode: table, STDLOG: 0 UPD 4
+ checked_mode: table, STDLOG: 0UPD 4
- checked_mode: table, STDLOG: 1 UPD 4
+ checked_mode: table, STDLOG: 1UPD 4
- checked_mode: table, STDLOG: 0 UPD 5
+ checked_mode: table, STDLOG: 0UPD 5
- checked_mode: table, STDLOG: 1 UPD 5
+ checked_mode: table, STDLOG: 1UPD 5
checked_mode: table, STDLOG: Records affected: 10
checked_mode: table, STDERR: Statement failed, SQLSTATE 21000
checked_mode: table, STDERR: Multiple source records cannot match the same target during MERGE
checked_mode: table, STDERR:
LOG DETAILS:
2025-07-01 06:04:43.934
2025-07-01 06:04:43.942 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-01 06:04:43.950 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12474/tmp_worker.sql')
2025-07-01 06:04:43.962 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12474/tmp_worker.log')
2025-07-01 06:04:43.972 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12474/tmp_worker.err')
2025-07-01 06:04:43.980 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-01 06:04:43.993
2025-07-01 06:04:44.007 @pytest.mark.trace
2025-07-01 06:04:44.018 @pytest.mark.version('>=4.0.2')
2025-07-01 06:04:44.027 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-01 06:04:44.034 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-01 06:04:44.045
2025-07-01 06:04:44.056 for checked_mode in('table', 'view'):
2025-07-01 06:04:44.068 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-01 06:04:44.078
2025-07-01 06:04:44.087 SQL_TO_BE_RESTARTED = f"""
2025-07-01 06:04:44.099 merge /* {SQL_TAG_THAT_WE_WAITING_FOR} */ into {target_obj} t
2025-07-01 06:04:44.107 using (
2025-07-01 06:04:44.117 select s.id, s.x from {target_obj} as s
2025-07-01 06:04:44.130 where s.id <= 1
2025-07-01 06:04:44.143 order by s.id DESC -- added only 05-jun-2024; thanks to Vlad.
2025-07-01 06:04:44.152 ) s
2025-07-01 06:04:44.161 on abs(t.id) = abs(s.id)
2025-07-01 06:04:44.168 when matched then
2025-07-01 06:04:44.174 update set t.x = s.id * 100
2025-07-01 06:04:44.179 """
2025-07-01 06:04:44.187
2025-07-01 06:04:44.198 sql_addi = f'''
2025-07-01 06:04:44.207 set term ^;
2025-07-01 06:04:44.214 execute block as
2025-07-01 06:04:44.225 begin
2025-07-01 06:04:44.239 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-01 06:04:44.251 end
2025-07-01 06:04:44.259 ^
2025-07-01 06:04:44.267 set term ;^
2025-07-01 06:04:44.275
2025-07-01 06:04:44.283 -- INITIAL DATA: add rows with ID = 0...6
2025-07-01 06:04:44.289 -- #############
2025-07-01 06:04:44.295 insert into {target_obj}(id, x)
2025-07-01 06:04:44.303 select row_number()over()-1, row_number()over()-1
2025-07-01 06:04:44.314 from rdb$types rows 6;
2025-07-01 06:04:44.326
2025-07-01 06:04:44.338 commit;
2025-07-01 06:04:44.350 '''
2025-07-01 06:04:44.360
2025-07-01 06:04:44.369 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-07-01 06:04:44.378 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-01 06:04:44.389 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-01 06:04:44.398 assert act.stderr == ''
2025-07-01 06:04:44.406 act.reset()
2025-07-01 06:04:44.416
2025-07-01 06:04:44.426 trace_cfg_items = [
2025-07-01 06:04:44.435 'time_threshold = 0',
2025-07-01 06:04:44.446 'log_errors = true',
2025-07-01 06:04:44.456 'log_statement_start = true',
2025-07-01 06:04:44.466 'log_statement_finish = true',
2025-07-01 06:04:44.477 ]
2025-07-01 06:04:44.489
2025-07-01 06:04:44.504 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-01 06:04:44.516
2025-07-01 06:04:44.528 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:44.539
2025-07-01 06:04:44.553 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-01 06:04:44.564 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-01 06:04:44.576 cur_monitoring = tx_monitoring.cursor()
2025-07-01 06:04:44.586
2025-07-01 06:04:44.595 cur_lock_1 = con_lock_1.cursor()
2025-07-01 06:04:44.603 cur_lock_2 = con_lock_2.cursor()
2025-07-01 06:04:44.614
2025-07-01 06:04:44.623 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-01 06:04:44.630 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-01 06:04:44.639 c.execute_immediate(sttm)
2025-07-01 06:04:44.652
2025-07-01 06:04:44.660
2025-07-01 06:04:44.667 #########################
2025-07-01 06:04:44.675 ### L O C K E R - 1 ###
2025-07-01 06:04:44.687 #########################
2025-07-01 06:04:44.697
2025-07-01 06:04:44.704 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = 0' )
2025-07-01 06:04:44.709
2025-07-01 06:04:44.713 worker_sql = f'''
2025-07-01 06:04:44.718 set list on;
2025-07-01 06:04:44.724 set autoddl off;
2025-07-01 06:04:44.729 set term ^;
2025-07-01 06:04:44.738 execute block as
2025-07-01 06:04:44.748 begin
2025-07-01 06:04:44.758 rdb$set_context('USER_SESSION','WHO', 'WORKER');
2025-07-01 06:04:44.769 end
2025-07-01 06:04:44.780 ^
2025-07-01 06:04:44.789 set term ;^
2025-07-01 06:04:44.796 commit;
2025-07-01 06:04:44.807 SET KEEP_TRAN_PARAMS ON;
2025-07-01 06:04:44.816 set transaction read committed read consistency;
2025-07-01 06:04:44.822 set list off;
2025-07-01 06:04:44.829 set wng off;
2025-07-01 06:04:44.835
2025-07-01 06:04:44.840 set count on;
2025-07-01 06:04:44.846 -- THIS MUST HANG:
2025-07-01 06:04:44.857 {SQL_TO_BE_RESTARTED};
2025-07-01 06:04:44.868
2025-07-01 06:04:44.879 -- check results:
2025-07-01 06:04:44.885 -- ###############
2025-07-01 06:04:44.892 select id,x from {target_obj} order by id;
2025-07-01 06:04:44.899
2025-07-01 06:04:44.907 select v.old_id, v.op, v.snap_no_rank
2025-07-01 06:04:44.918 from v_worker_log v
2025-07-01 06:04:44.926 where v.op = 'upd';
2025-07-01 06:04:44.933
2025-07-01 06:04:44.939
2025-07-01 06:04:44.946 --set width who 10;
2025-07-01 06:04:44.958 -- DO NOT check this! Values can differ here from one run to another!
2025-07-01 06:04:44.967 -- 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:44.979 rollback;
2025-07-01 06:04:44.988
2025-07-01 06:04:44.998 '''
2025-07-01 06:04:45.008
2025-07-01 06:04:45.020 fn_worker_sql.write_text(worker_sql)
2025-07-01 06:04:45.029
2025-07-01 06:04:45.035 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-01 06:04:45.040
2025-07-01 06:04:45.049 ############################################################################
2025-07-01 06:04:45.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-01 06:04:45.071 ############################################################################
2025-07-01 06:04:45.080 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-01 06:04:45.087 '-user', act.db.user,
2025-07-01 06:04:45.095 '-password', act.db.password,
2025-07-01 06:04:45.107 '-pag', '999999',
2025-07-01 06:04:45.122 act.db.dsn
2025-07-01 06:04:45.133 ],
2025-07-01 06:04:45.142 stdout = hang_out,
2025-07-01 06:04:45.151 stderr = hang_err
2025-07-01 06:04:45.164 )
2025-07-01 06:04:45.174
2025-07-01 06:04:45.187 # NB: when ISQL will establish attach, first record that it must lock is ID = 0 -- see above SQL_TO_BE_RESTARTED
2025-07-01 06:04:45.201 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:04:45.213 #
2025-07-01 06:04:45.228 #wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id = 0', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:04:45.237
2025-07-01 06:04:45.247 sttm = f'update {target_obj} set id = ? where abs( id ) = ?'
2025-07-01 06:04:45.256
2025-07-01 06:04:45.262 #########################
2025-07-01 06:04:45.269 ### L O C K E R - 2 ###
2025-07-01 06:04:45.275 #########################
2025-07-01 06:04:45.282 cur_lock_2.execute( sttm, ( -5, 5, ) )
2025-07-01 06:04:45.288 con_lock_2.commit()
2025-07-01 06:04:45.294 cur_lock_2.execute( sttm, ( -5, 5, ) )
2025-07-01 06:04:45.300
2025-07-01 06:04:45.306 #########################
2025-07-01 06:04:45.314 ### L O C K E R - 1 ###
2025-07-01 06:04:45.320 #########################
2025-07-01 06:04:45.333 con_lock_1.commit() # releases record with ID = 0 ==> now it can be locked by worker.
2025-07-01 06:04:45.342 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:04:45.348 #
2025-07-01 06:04:45.354 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=0', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:04:45.363
2025-07-01 06:04:45.371
2025-07-01 06:04:45.378 cur_lock_1.execute( sttm, ( -4, 4, ) )
2025-07-01 06:04:45.388 con_lock_1.commit()
2025-07-01 06:04:45.399 cur_lock_1.execute( sttm, ( -4, 4, ) )
2025-07-01 06:04:45.407
2025-07-01 06:04:45.413 #########################
2025-07-01 06:04:45.420 ### L O C K E R - 2 ###
2025-07-01 06:04:45.425 #########################
2025-07-01 06:04:45.433 con_lock_2.commit() # releases record with ID = -5 ==> now it can be locked by worker.
2025-07-01 06:04:45.445 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:04:45.454 #
2025-07-01 06:04:45.462 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:45.471
2025-07-01 06:04:45.482 cur_lock_2.execute( sttm, ( -3, 3, ) )
2025-07-01 06:04:45.490 con_lock_2.commit()
2025-07-01 06:04:45.498 cur_lock_2.execute( sttm, ( -3, 3, ) )
2025-07-01 06:04:45.508
2025-07-01 06:04:45.518 #########################
2025-07-01 06:04:45.531 ### L O C K E R - 1 ###
2025-07-01 06:04:45.544 #########################
2025-07-01 06:04:45.551 con_lock_1.commit()
2025-07-01 06:04:45.558 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:04:45.568 #
2025-07-01 06:04:45.580 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=-4', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:04:45.591
2025-07-01 06:04:45.598 cur_lock_1.execute( sttm, ( -2, 2, ) )
2025-07-01 06:04:45.605 con_lock_1.commit()
2025-07-01 06:04:45.612 cur_lock_1.execute( sttm, ( -2, 2, ) )
2025-07-01 06:04:45.618
2025-07-01 06:04:45.625 #########################
2025-07-01 06:04:45.632 ### L O C K E R - 2 ###
2025-07-01 06:04:45.642 #########################
2025-07-01 06:04:45.650 con_lock_2.commit()
2025-07-01 06:04:45.662 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:04:45.672 #
2025-07-01 06:04:45.680 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=-3', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:04:45.686
2025-07-01 06:04:45.691
2025-07-01 06:04:45.698 cur_lock_2.execute( f'insert into {target_obj}(id,x) values(?, ?)', ( -1, 1, ) )
2025-07-01 06:04:45.705 con_lock_2.commit()
2025-07-01 06:04:45.716 cur_lock_2.execute( f'update {target_obj} set id = id where id = ?', ( -1, ) )
2025-07-01 06:04:45.723
2025-07-01 06:04:45.735 #########################
2025-07-01 06:04:45.744 ### L O C K E R - 1 ###
2025-07-01 06:04:45.752 #########################
2025-07-01 06:04:45.759 con_lock_1.commit()
2025-07-01 06:04:45.767 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:04:45.773 #
2025-07-01 06:04:45.779 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-01 06:04:45.787
2025-07-01 06:04:45.798 #########################
2025-07-01 06:04:45.807 ### L O C K E R - 2 ###
2025-07-01 06:04:45.815 #########################
2025-07-01 06:04:45.822 con_lock_2.commit() # At this point merge can complete its job but it must FAIL because of multiple matches for abs(t.id) = abs(s.id), i.e. when ID = -1 and 1
2025-07-01 06:04:45.828
2025-07-01 06:04:45.834 # Here we wait for ISQL complete its mission:
2025-07-01 06:04:45.845 p_worker.wait()
2025-07-01 06:04:45.853
2025-07-01 06:04:45.860 # < with act.db.connect
2025-07-01 06:04:45.867
2025-07-01 06:04:45.876 for g in (fn_worker_log, fn_worker_err):
2025-07-01 06:04:45.885 with g.open() as f:
2025-07-01 06:04:45.898 for line in f:
2025-07-01 06:04:45.909 if line.strip():
2025-07-01 06:04:45.921 print(f'checked_mode: {checked_mode}, {"STDLOG" if g == fn_worker_log else "STDERR"}: {line}')
2025-07-01 06:04:45.934
2025-07-01 06:04:45.947 expected_stdout_worker = f"""
2025-07-01 06:04:45.956 checked_mode: {checked_mode}, STDLOG: Records affected: 2
2025-07-01 06:04:45.963 checked_mode: {checked_mode}, STDLOG: ID X
2025-07-01 06:04:45.971 checked_mode: {checked_mode}, STDLOG: ======= =======
2025-07-01 06:04:45.977 checked_mode: {checked_mode}, STDLOG: -5 5
2025-07-01 06:04:45.983 checked_mode: {checked_mode}, STDLOG: -4 4
2025-07-01 06:04:45.988 checked_mode: {checked_mode}, STDLOG: -3 3
2025-07-01 06:04:45.994 checked_mode: {checked_mode}, STDLOG: -2 2
2025-07-01 06:04:46.000 checked_mode: {checked_mode}, STDLOG: -1 1
2025-07-01 06:04:46.007 checked_mode: {checked_mode}, STDLOG: 0 0
2025-07-01 06:04:46.015 checked_mode: {checked_mode}, STDLOG: 1 1
2025-07-01 06:04:46.025 checked_mode: {checked_mode}, STDLOG: Records affected: 7
2025-07-01 06:04:46.037 checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:04:46.049 checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
2025-07-01 06:04:46.060 checked_mode: {checked_mode}, STDLOG: 0 UPD 1
2025-07-01 06:04:46.071 checked_mode: {checked_mode}, STDLOG: 1 UPD 1
2025-07-01 06:04:46.080 checked_mode: {checked_mode}, STDLOG: 0 UPD 2
2025-07-01 06:04:46.088 checked_mode: {checked_mode}, STDLOG: 1 UPD 2
2025-07-01 06:04:46.095 checked_mode: {checked_mode}, STDLOG: 0 UPD 3
2025-07-01 06:04:46.103 checked_mode: {checked_mode}, STDLOG: 1 UPD 3
2025-07-01 06:04:46.114 checked_mode: {checked_mode}, STDLOG: 0 UPD 4
2025-07-01 06:04:46.126 checked_mode: {checked_mode}, STDLOG: 1 UPD 4
2025-07-01 06:04:46.137 checked_mode: {checked_mode}, STDLOG: 0 UPD 5
2025-07-01 06:04:46.150 checked_mode: {checked_mode}, STDLOG: 1 UPD 5
2025-07-01 06:04:46.161 checked_mode: {checked_mode}, STDLOG: Records affected: 10
2025-07-01 06:04:46.172 checked_mode: {checked_mode}, STDERR: Statement failed, SQLSTATE = 21000
2025-07-01 06:04:46.182 checked_mode: {checked_mode}, STDERR: Multiple source records cannot match the same target during MERGE
2025-07-01 06:04:46.190 checked_mode: {checked_mode}, STDERR:
2025-07-01 06:04:46.196 """
2025-07-01 06:04:46.202
2025-07-01 06:04:46.206 act.expected_stdout = expected_stdout_worker
2025-07-01 06:04:46.211 act.stdout = capsys.readouterr().out
2025-07-01 06:04:46.217 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-01 06:04:46.223 E assert
2025-07-01 06:04:46.229 E checked_mode: table, STDLOG: Records affected: 2
2025-07-01 06:04:46.235 E checked_mode: table, STDLOG: ID X
2025-07-01 06:04:46.241 E checked_mode: table, STDLOG:
2025-07-01 06:04:46.246 E checked_mode: table, STDLOG: -5 5
2025-07-01 06:04:46.254 E checked_mode: table, STDLOG: -4 4
2025-07-01 06:04:46.264 E checked_mode: table, STDLOG: -3 3
2025-07-01 06:04:46.273 E checked_mode: table, STDLOG: -2 2
2025-07-01 06:04:46.281 E checked_mode: table, STDLOG: -1 1
2025-07-01 06:04:46.293 E checked_mode: table, STDLOG: 0 0
2025-07-01 06:04:46.301 E checked_mode: table, STDLOG: 1 1
2025-07-01 06:04:46.307 E checked_mode: table, STDLOG: Records affected: 7
2025-07-01 06:04:46.312 E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:04:46.318 E checked_mode: table, STDLOG:
2025-07-01 06:04:46.328 E - checked_mode: table, STDLOG: 0 UPD 1
2025-07-01 06:04:46.346 E + checked_mode: table, STDLOG: 0UPD 1
2025-07-01 06:04:46.352 E - checked_mode: table, STDLOG: 1 UPD 1
2025-07-01 06:04:46.367 E + checked_mode: table, STDLOG: 1UPD 1
2025-07-01 06:04:46.379 E - checked_mode: table, STDLOG: 0 UPD 2
2025-07-01 06:04:46.396 E + checked_mode: table, STDLOG: 0UPD 2
2025-07-01 06:04:46.403 E - checked_mode: table, STDLOG: 1 UPD 2
2025-07-01 06:04:46.415 E + checked_mode: table, STDLOG: 1UPD 2
2025-07-01 06:04:46.421 E - checked_mode: table, STDLOG: 0 UPD 3
2025-07-01 06:04:46.435 E + checked_mode: table, STDLOG: 0UPD 3
2025-07-01 06:04:46.442 E - checked_mode: table, STDLOG: 1 UPD 3
2025-07-01 06:04:46.463 E + checked_mode: table, STDLOG: 1UPD 3
2025-07-01 06:04:46.470 E - checked_mode: table, STDLOG: 0 UPD 4
2025-07-01 06:04:46.481 E + checked_mode: table, STDLOG: 0UPD 4
2025-07-01 06:04:46.486 E - checked_mode: table, STDLOG: 1 UPD 4
2025-07-01 06:04:46.498 E + checked_mode: table, STDLOG: 1UPD 4
2025-07-01 06:04:46.504 E - checked_mode: table, STDLOG: 0 UPD 5
2025-07-01 06:04:46.513 E + checked_mode: table, STDLOG: 0UPD 5
2025-07-01 06:04:46.519 E - checked_mode: table, STDLOG: 1 UPD 5
2025-07-01 06:04:46.539 E + checked_mode: table, STDLOG: 1UPD 5
2025-07-01 06:04:46.546 E checked_mode: table, STDLOG: Records affected: 10
2025-07-01 06:04:46.556 E checked_mode: table, STDERR: Statement failed, SQLSTATE 21000
2025-07-01 06:04:46.565 E checked_mode: table, STDERR: Multiple source records cannot match the same target during MERGE
2025-07-01 06:04:46.572 E checked_mode: table, STDERR:
2025-07-01 06:04:46.579
2025-07-01 06:04:46.586 tests/functional/transactions/test_read_consist_sttm_merge_deny_multiple_matches.py:421: AssertionError
2025-07-01 06:04:46.595 ---------------------------- Captured stdout setup -----------------------------
2025-07-01 06:04:46.604 Creating db: localhost:/var/tmp/qa_2024/test_12474/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_12474/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12474/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12474/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"""
merge /* {SQL_TAG_THAT_WE_WAITING_FOR} */ into {target_obj} t
using (
select s.id, s.x from {target_obj} as s
where s.id <= 1
order by s.id DESC -- added only 05-jun-2024; thanks to Vlad.
) s
on abs(t.id) = abs(s.id)
when matched then
update set t.x = s.id * 100
"""
sql_addi = f'''
set term ^;
execute block as
begin
rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
end
^
set term ;^
-- INITIAL DATA: add rows with ID = 0...6
-- #############
insert into {target_obj}(id, x)
select row_number()over()-1, row_number()over()-1
from rdb$types rows 6;
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()
cur_lock_1 = con_lock_1.cursor()
cur_lock_2 = con_lock_2.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 = 0' )
worker_sql = f'''
set list on;
set autoddl off;
set term ^;
execute block as
begin
rdb$set_context('USER_SESSION','WHO', 'WORKER');
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:
{SQL_TO_BE_RESTARTED};
-- check results:
-- ###############
select id,x from {target_obj} order by id;
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 = 0 -- 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 = 0', SQL_TAG_THAT_WE_WAITING_FOR)
sttm = f'update {target_obj} set id = ? where abs( id ) = ?'
#########################
### L O C K E R - 2 ###
#########################
cur_lock_2.execute( sttm, ( -5, 5, ) )
con_lock_2.commit()
cur_lock_2.execute( sttm, ( -5, 5, ) )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit() # releases record with ID = 0 ==> now it can be locked by worker.
# 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=0', SQL_TAG_THAT_WE_WAITING_FOR)
cur_lock_1.execute( sttm, ( -4, 4, ) )
con_lock_1.commit()
cur_lock_1.execute( sttm, ( -4, 4, ) )
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.commit() # releases record with ID = -5 ==> now it can be locked by worker.
# 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)
cur_lock_2.execute( sttm, ( -3, 3, ) )
con_lock_2.commit()
cur_lock_2.execute( sttm, ( -3, 3, ) )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit()
# 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=-4', SQL_TAG_THAT_WE_WAITING_FOR)
cur_lock_1.execute( sttm, ( -2, 2, ) )
con_lock_1.commit()
cur_lock_1.execute( sttm, ( -2, 2, ) )
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.commit()
# 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=-3', SQL_TAG_THAT_WE_WAITING_FOR)
cur_lock_2.execute( f'insert into {target_obj}(id,x) values(?, ?)', ( -1, 1, ) )
con_lock_2.commit()
cur_lock_2.execute( f'update {target_obj} set id = id where id = ?', ( -1, ) )
#########################
### L O C K E R - 1 ###
#########################
con_lock_1.commit()
# We must to ensure that this (worker) attachment has been really created and LOCKS this record:
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set id=id where id=-2', SQL_TAG_THAT_WE_WAITING_FOR)
#########################
### L O C K E R - 2 ###
#########################
con_lock_2.commit() # At this point merge can complete its job but it must FAIL because of multiple matches for abs(t.id) = abs(s.id), i.e. when ID = -1 and 1
# 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.strip():
print(f'checked_mode: {checked_mode}, {"STDLOG" if g == fn_worker_log else "STDERR"}: {line}')
expected_stdout_worker = f"""
checked_mode: {checked_mode}, STDLOG: Records affected: 2
checked_mode: {checked_mode}, STDLOG: ID X
checked_mode: {checked_mode}, STDLOG: ======= =======
checked_mode: {checked_mode}, STDLOG: -5 5
checked_mode: {checked_mode}, STDLOG: -4 4
checked_mode: {checked_mode}, STDLOG: -3 3
checked_mode: {checked_mode}, STDLOG: -2 2
checked_mode: {checked_mode}, STDLOG: -1 1
checked_mode: {checked_mode}, STDLOG: 0 0
checked_mode: {checked_mode}, STDLOG: 1 1
checked_mode: {checked_mode}, STDLOG: Records affected: 7
checked_mode: {checked_mode}, STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, STDLOG: 0 UPD 1
checked_mode: {checked_mode}, STDLOG: 1 UPD 1
checked_mode: {checked_mode}, STDLOG: 0 UPD 2
checked_mode: {checked_mode}, STDLOG: 1 UPD 2
checked_mode: {checked_mode}, STDLOG: 0 UPD 3
checked_mode: {checked_mode}, STDLOG: 1 UPD 3
checked_mode: {checked_mode}, STDLOG: 0 UPD 4
checked_mode: {checked_mode}, STDLOG: 1 UPD 4
checked_mode: {checked_mode}, STDLOG: 0 UPD 5
checked_mode: {checked_mode}, STDLOG: 1 UPD 5
checked_mode: {checked_mode}, STDLOG: Records affected: 10
checked_mode: {checked_mode}, STDERR: Statement failed, SQLSTATE = 21000
checked_mode: {checked_mode}, STDERR: Multiple source records cannot match the same target during MERGE
checked_mode: {checked_mode}, STDERR:
"""
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: 2
E checked_mode: table, STDLOG: ID X
E checked_mode: table, STDLOG:
E checked_mode: table, STDLOG: -5 5
E checked_mode: table, STDLOG: -4 4
E checked_mode: table, STDLOG: -3 3
E checked_mode: table, STDLOG: -2 2
E checked_mode: table, STDLOG: -1 1
E checked_mode: table, STDLOG: 0 0
E checked_mode: table, STDLOG: 1 1
E checked_mode: table, STDLOG: Records affected: 7
E checked_mode: table, STDLOG: OLD_ID OP SNAP_NO_RANK
E checked_mode: table, STDLOG:
E - checked_mode: table, STDLOG: 0 UPD 1
E + checked_mode: table, STDLOG: 0UPD 1
E - checked_mode: table, STDLOG: 1 UPD 1
E + checked_mode: table, STDLOG: 1UPD 1
E - checked_mode: table, STDLOG: 0 UPD 2
E + checked_mode: table, STDLOG: 0UPD 2
E - checked_mode: table, STDLOG: 1 UPD 2
E + checked_mode: table, STDLOG: 1UPD 2
E - checked_mode: table, STDLOG: 0 UPD 3
E + checked_mode: table, STDLOG: 0UPD 3
E - checked_mode: table, STDLOG: 1 UPD 3
E + checked_mode: table, STDLOG: 1UPD 3
E - checked_mode: table, STDLOG: 0 UPD 4
E + checked_mode: table, STDLOG: 0UPD 4
E - checked_mode: table, STDLOG: 1 UPD 4
E + checked_mode: table, STDLOG: 1UPD 4
E - checked_mode: table, STDLOG: 0 UPD 5
E + checked_mode: table, STDLOG: 0UPD 5
E - checked_mode: table, STDLOG: 1 UPD 5
E + checked_mode: table, STDLOG: 1UPD 5
E checked_mode: table, STDLOG: Records affected: 10
E checked_mode: table, STDERR: Statement failed, SQLSTATE 21000
E checked_mode: table, STDERR: Multiple source records cannot match the same target during MERGE
E checked_mode: table, STDERR:
tests/functional/transactions/test_read_consist_sttm_merge_deny_multiple_matches.py:421: AssertionError
|