Check firebird.log [no messages found for interval when this test was running]
Jump to: output_first_mismatch    outcomes_full_history    elapsed_time_chart
Show cross-report outcomes.

Annotation type Annotation details
2 @message
assert   
    EXECUTE_STATEMENT_RESTART
    Restarted 1 time(s)
    EXECUTE_STATEMENT_RESTART
    Restarted 2 time(s)
    EXECUTE_STATEMENT_RESTART
    Restarted 3 time(s)
    EXECUTE_STATEMENT_RESTART
    Restarted 4 time(s)
  + EXECUTE_STATEMENT_RESTART
  + Restarted 5 time(s)

LOG DETAILS:

2025-06-10 14:06:45.329
2025-06-10 14:06:45.335 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-10 14:06:45.347 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12376/tmp_worker.sql')
2025-06-10 14:06:45.354 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12376/tmp_worker.log')
2025-06-10 14:06:45.364 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12376/tmp_worker.err')
2025-06-10 14:06:45.377 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-10 14:06:45.388
2025-06-10 14:06:45.395 @pytest.mark.trace
2025-06-10 14:06:45.401 @pytest.mark.version('>=4.0.2')
2025-06-10 14:06:45.406 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-06-10 14:06:45.413 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-06-10 14:06:45.419
2025-06-10 14:06:45.425 for checked_mode in('table', 'view'):
2025-06-10 14:06:45.432 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-06-10 14:06:45.438
2025-06-10 14:06:45.447 SQL_TO_BE_RESTARTED = f"""
2025-06-10 14:06:45.455 merge /* {SQL_TAG_THAT_WE_WAITING_FOR} */ into {target_obj} t
2025-06-10 14:06:45.463 using (
2025-06-10 14:06:45.470 select s.id, s.x from {target_obj} as s
2025-06-10 14:06:45.475 where s.id <= 1
2025-06-10 14:06:45.480 order by s.id DESC -- added only 05-jun-2024; thanks to Vlad.
2025-06-10 14:06:45.486 ) s
2025-06-10 14:06:45.492 on abs(t.id) = abs(s.id)
2025-06-10 14:06:45.498 when matched then
2025-06-10 14:06:45.504 update set t.x = s.id * 100
2025-06-10 14:06:45.512 """
2025-06-10 14:06:45.519
2025-06-10 14:06:45.529 sql_addi = f'''
2025-06-10 14:06:45.537 set term ^;
2025-06-10 14:06:45.543 execute block as
2025-06-10 14:06:45.549 begin
2025-06-10 14:06:45.555 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-06-10 14:06:45.561 end
2025-06-10 14:06:45.567 ^
2025-06-10 14:06:45.574 set term ;^
2025-06-10 14:06:45.580
2025-06-10 14:06:45.590 -- INITIAL DATA: add rows with ID = 0...6
2025-06-10 14:06:45.596 -- #############
2025-06-10 14:06:45.603 insert into {target_obj}(id, x)
2025-06-10 14:06:45.609 select row_number()over()-1, row_number()over()-1
2025-06-10 14:06:45.615 from rdb$types rows 6;
2025-06-10 14:06:45.622
2025-06-10 14:06:45.628 commit;
2025-06-10 14:06:45.635 '''
2025-06-10 14:06:45.642
2025-06-10 14:06:45.649 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-06-10 14:06:45.661 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-06-10 14:06:45.672 # See also letter from dimitr, 01-feb-2022 14:46
2025-06-10 14:06:45.681 assert act.stderr == ''
2025-06-10 14:06:45.693 act.reset()
2025-06-10 14:06:45.705
2025-06-10 14:06:45.713 trace_cfg_items = [
2025-06-10 14:06:45.723 'time_threshold = 0',
2025-06-10 14:06:45.730 'log_errors = true',
2025-06-10 14:06:45.737 'log_statement_start = true',
2025-06-10 14:06:45.743 'log_statement_finish = true',
2025-06-10 14:06:45.748 ]
2025-06-10 14:06:45.754
2025-06-10 14:06:45.761 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-06-10 14:06:45.766
2025-06-10 14:06:45.772 with act.db.connect() as con_lock_1, act.db.connect() as con_lock_2, act.db.connect() as con_monitoring:
2025-06-10 14:06:45.777
2025-06-10 14:06:45.782 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-06-10 14:06:45.788 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-06-10 14:06:45.793 cur_monitoring = tx_monitoring.cursor()
2025-06-10 14:06:45.798
2025-06-10 14:06:45.803 cur_lock_1 = con_lock_1.cursor()
2025-06-10 14:06:45.809 cur_lock_2 = con_lock_2.cursor()
2025-06-10 14:06:45.814
2025-06-10 14:06:45.820 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-06-10 14:06:45.830 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-06-10 14:06:45.843 c.execute_immediate(sttm)
2025-06-10 14:06:45.853
2025-06-10 14:06:45.863
2025-06-10 14:06:45.877 #########################
2025-06-10 14:06:45.886 ###  L O C K E R - 1  ###
2025-06-10 14:06:45.896 #########################
2025-06-10 14:06:45.905
2025-06-10 14:06:45.914 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = 0' )
2025-06-10 14:06:45.925
2025-06-10 14:06:45.933 worker_sql = f'''
2025-06-10 14:06:45.940 set list on;
2025-06-10 14:06:45.946 set autoddl off;
2025-06-10 14:06:45.954 set term ^;
2025-06-10 14:06:45.963 execute block as
2025-06-10 14:06:45.971 begin
2025-06-10 14:06:45.980 rdb$set_context('USER_SESSION','WHO', 'WORKER');
2025-06-10 14:06:45.988 end
2025-06-10 14:06:45.996 ^
2025-06-10 14:06:46.005 set term ;^
2025-06-10 14:06:46.018 commit;
2025-06-10 14:06:46.028 SET KEEP_TRAN_PARAMS ON;
2025-06-10 14:06:46.038 set transaction read committed read consistency;
2025-06-10 14:06:46.044 set list off;
2025-06-10 14:06:46.052 set wng off;
2025-06-10 14:06:46.059
2025-06-10 14:06:46.072 set count on;
2025-06-10 14:06:46.085 -- THIS MUST HANG:
2025-06-10 14:06:46.095 {SQL_TO_BE_RESTARTED};
2025-06-10 14:06:46.105
2025-06-10 14:06:46.118 -- check results:
2025-06-10 14:06:46.132 -- ###############
2025-06-10 14:06:46.146 select id,x from {target_obj} order by id;
2025-06-10 14:06:46.158
2025-06-10 14:06:46.167 select v.old_id, v.op, v.snap_no_rank
2025-06-10 14:06:46.175 from v_worker_log v
2025-06-10 14:06:46.182 where v.op = 'upd';
2025-06-10 14:06:46.188
2025-06-10 14:06:46.195
2025-06-10 14:06:46.203 --set width who 10;
2025-06-10 14:06:46.216 -- DO NOT check this! Values can differ here from one run to another!
2025-06-10 14:06:46.226 -- select id, trn, who, old_id, new_id, op, rec_vers, global_cn, snap_no from tlog_done order by id;
2025-06-10 14:06:46.232 rollback;
2025-06-10 14:06:46.238
2025-06-10 14:06:46.247 '''
2025-06-10 14:06:46.258
2025-06-10 14:06:46.265 fn_worker_sql.write_text(worker_sql)
2025-06-10 14:06:46.273
2025-06-10 14:06:46.280 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-06-10 14:06:46.287
2025-06-10 14:06:46.294 ############################################################################
2025-06-10 14:06:46.310 ###  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-06-10 14:06:46.321 ############################################################################
2025-06-10 14:06:46.329 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-06-10 14:06:46.336 '-user', act.db.user,
2025-06-10 14:06:46.343 '-password', act.db.password,
2025-06-10 14:06:46.351 '-pag', '999999',
2025-06-10 14:06:46.358 act.db.dsn
2025-06-10 14:06:46.370 ],
2025-06-10 14:06:46.380 stdout = hang_out,
2025-06-10 14:06:46.388 stderr = hang_err
2025-06-10 14:06:46.395 )
2025-06-10 14:06:46.400
2025-06-10 14:06:46.407 # NB: when ISQL will establish attach, first record that it must lock is ID = 0 -- see above SQL_TO_BE_RESTARTED
2025-06-10 14:06:46.413 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-06-10 14:06:46.421 #
2025-06-10 14:06:46.428 #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-06-10 14:06:46.436
2025-06-10 14:06:46.443 sttm = f'update {target_obj} set id = ? where abs( id ) = ?'
2025-06-10 14:06:46.450
2025-06-10 14:06:46.460 #########################
2025-06-10 14:06:46.471 ###  L O C K E R - 2  ###
2025-06-10 14:06:46.481 #########################
2025-06-10 14:06:46.492 cur_lock_2.execute( sttm, ( -5, 5, ) )
2025-06-10 14:06:46.499 con_lock_2.commit()
2025-06-10 14:06:46.505 cur_lock_2.execute( sttm, ( -5, 5, ) )
2025-06-10 14:06:46.511
2025-06-10 14:06:46.517 #########################
2025-06-10 14:06:46.524 ###  L O C K E R - 1  ###
2025-06-10 14:06:46.531 #########################
2025-06-10 14:06:46.539 con_lock_1.commit() # releases record with ID = 0 ==> now it can be locked by worker.
2025-06-10 14:06:46.548 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-06-10 14:06:46.559 #
2025-06-10 14:06:46.566 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-06-10 14:06:46.573
2025-06-10 14:06:46.581
2025-06-10 14:06:46.591 cur_lock_1.execute( sttm, ( -4, 4, ) )
2025-06-10 14:06:46.601 con_lock_1.commit()
2025-06-10 14:06:46.607 cur_lock_1.execute( sttm, ( -4, 4, ) )
2025-06-10 14:06:46.613
2025-06-10 14:06:46.618 #########################
2025-06-10 14:06:46.623 ###  L O C K E R - 2  ###
2025-06-10 14:06:46.628 #########################
2025-06-10 14:06:46.634 con_lock_2.commit() # releases record with ID = -5 ==> now it can be locked by worker.
2025-06-10 14:06:46.639 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-06-10 14:06:46.644 #
2025-06-10 14:06:46.649 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-06-10 14:06:46.654
2025-06-10 14:06:46.660 cur_lock_2.execute( sttm, ( -3, 3, ) )
2025-06-10 14:06:46.666 con_lock_2.commit()
2025-06-10 14:06:46.672 cur_lock_2.execute( sttm, ( -3, 3, ) )
2025-06-10 14:06:46.679
2025-06-10 14:06:46.685 #########################
2025-06-10 14:06:46.691 ###  L O C K E R - 1  ###
2025-06-10 14:06:46.697 #########################
2025-06-10 14:06:46.704 con_lock_1.commit()
2025-06-10 14:06:46.712 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-06-10 14:06:46.719 #
2025-06-10 14:06:46.727 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-06-10 14:06:46.734
2025-06-10 14:06:46.743 cur_lock_1.execute( sttm, ( -2, 2, ) )
2025-06-10 14:06:46.749 con_lock_1.commit()
2025-06-10 14:06:46.756 cur_lock_1.execute( sttm, ( -2, 2, ) )
2025-06-10 14:06:46.762
2025-06-10 14:06:46.769 #########################
2025-06-10 14:06:46.775 ###  L O C K E R - 2  ###
2025-06-10 14:06:46.781 #########################
2025-06-10 14:06:46.787 con_lock_2.commit()
2025-06-10 14:06:46.794 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-06-10 14:06:46.803 #
2025-06-10 14:06:46.815 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-06-10 14:06:46.822
2025-06-10 14:06:46.829
2025-06-10 14:06:46.836 cur_lock_2.execute( f'insert into {target_obj}(id,x) values(?, ?)', ( -1, 1, ) )
2025-06-10 14:06:46.844 con_lock_2.commit()
2025-06-10 14:06:46.852 cur_lock_2.execute( f'update {target_obj} set id = id where id = ?', ( -1, ) )
2025-06-10 14:06:46.859
2025-06-10 14:06:46.866 #########################
2025-06-10 14:06:46.877 ###  L O C K E R - 1  ###
2025-06-10 14:06:46.888 #########################
2025-06-10 14:06:46.901 con_lock_1.commit()
2025-06-10 14:06:46.914 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-06-10 14:06:46.923 #
2025-06-10 14:06:46.930 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-06-10 14:06:46.937
2025-06-10 14:06:46.943 #########################
2025-06-10 14:06:46.950 ###  L O C K E R - 2  ###
2025-06-10 14:06:46.960 #########################
2025-06-10 14:06:46.973 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-06-10 14:06:46.984
2025-06-10 14:06:46.992 # Here we wait for ISQL complete its mission:
2025-06-10 14:06:47.000 p_worker.wait()
2025-06-10 14:06:47.006
2025-06-10 14:06:47.013 # < with act.db.connect
2025-06-10 14:06:47.018
2025-06-10 14:06:47.027 for g in (fn_worker_log, fn_worker_err):
2025-06-10 14:06:47.035 with g.open() as f:
2025-06-10 14:06:47.043 for line in f:
2025-06-10 14:06:47.049 if line.strip():
2025-06-10 14:06:47.055 print(f'checked_mode: {checked_mode}, {"STDLOG" if g == fn_worker_log else "STDERR"}: {line}')
2025-06-10 14:06:47.061
2025-06-10 14:06:47.067 expected_stdout_worker = f"""
2025-06-10 14:06:47.072 checked_mode: {checked_mode}, STDLOG: Records affected: 2
2025-06-10 14:06:47.079 checked_mode: {checked_mode}, STDLOG:      ID       X
2025-06-10 14:06:47.086 checked_mode: {checked_mode}, STDLOG: ======= =======
2025-06-10 14:06:47.093 checked_mode: {checked_mode}, STDLOG:      -5       5
2025-06-10 14:06:47.099 checked_mode: {checked_mode}, STDLOG:      -4       4
2025-06-10 14:06:47.108 checked_mode: {checked_mode}, STDLOG:      -3       3
2025-06-10 14:06:47.120 checked_mode: {checked_mode}, STDLOG:      -2       2
2025-06-10 14:06:47.128 checked_mode: {checked_mode}, STDLOG:      -1       1
2025-06-10 14:06:47.136 checked_mode: {checked_mode}, STDLOG:       0       0
2025-06-10 14:06:47.142 checked_mode: {checked_mode}, STDLOG:       1       1
2025-06-10 14:06:47.154 checked_mode: {checked_mode}, STDLOG: Records affected: 7
2025-06-10 14:06:47.164 checked_mode: {checked_mode}, STDLOG:  OLD_ID OP              SNAP_NO_RANK
2025-06-10 14:06:47.173 checked_mode: {checked_mode}, STDLOG: ======= ====== =====================
2025-06-10 14:06:47.186 checked_mode: {checked_mode}, STDLOG:       0 UPD                        1
2025-06-10 14:06:47.197 checked_mode: {checked_mode}, STDLOG:       1 UPD                        1
2025-06-10 14:06:47.212 checked_mode: {checked_mode}, STDLOG:       0 UPD                        2
2025-06-10 14:06:47.223 checked_mode: {checked_mode}, STDLOG:       1 UPD                        2
2025-06-10 14:06:47.233 checked_mode: {checked_mode}, STDLOG:       0 UPD                        3
2025-06-10 14:06:47.242 checked_mode: {checked_mode}, STDLOG:       1 UPD                        3
2025-06-10 14:06:47.252 checked_mode: {checked_mode}, STDLOG:       0 UPD                        4
2025-06-10 14:06:47.264 checked_mode: {checked_mode}, STDLOG:       1 UPD                        4
2025-06-10 14:06:47.276 checked_mode: {checked_mode}, STDLOG:       0 UPD                        5
2025-06-10 14:06:47.287 checked_mode: {checked_mode}, STDLOG:       1 UPD                        5
2025-06-10 14:06:47.295 checked_mode: {checked_mode}, STDLOG: Records affected: 10
2025-06-10 14:06:47.308 checked_mode: {checked_mode}, STDERR: Statement failed, SQLSTATE = 21000
2025-06-10 14:06:47.319 checked_mode: {checked_mode}, STDERR: Multiple source records cannot match the same target during MERGE
2025-06-10 14:06:47.327 checked_mode: {checked_mode}, STDERR:
2025-06-10 14:06:47.334 """
2025-06-10 14:06:47.340
2025-06-10 14:06:47.347 act.expected_stdout = expected_stdout_worker
2025-06-10 14:06:47.358 act.stdout = capsys.readouterr().out
2025-06-10 14:06:47.369 assert act.clean_stdout == act.clean_expected_stdout
2025-06-10 14:06:47.381 act.reset()
2025-06-10 14:06:47.387
2025-06-10 14:06:47.398 # < with act.trace
2025-06-10 14:06:47.407
2025-06-10 14:06:47.414 allowed_patterns = \
2025-06-10 14:06:47.420 [
2025-06-10 14:06:47.427 '\\)\\s+EXECUTE_STATEMENT_RESTART$'
2025-06-10 14:06:47.436 #,re.escape(SQL_TO_BE_RESTARTED)
2025-06-10 14:06:47.445 ,'^Restarted \\d+ time\\(s\\)'
2025-06-10 14:06:47.456 ]
2025-06-10 14:06:47.466 allowed_patterns = [re.compile(x) for x in allowed_patterns]
2025-06-10 14:06:47.475
2025-06-10 14:06:47.484 for line in act.trace_log:
2025-06-10 14:06:47.491 if line.strip():
2025-06-10 14:06:47.497 if act.match_any(line.strip(), allowed_patterns):
2025-06-10 14:06:47.503 print(line.strip())
2025-06-10 14:06:47.511
2025-06-10 14:06:47.519 expected_stdout_trace = f"""
2025-06-10 14:06:47.527 EXECUTE_STATEMENT_RESTART
2025-06-10 14:06:47.540 Restarted 1 time(s)
2025-06-10 14:06:47.551
2025-06-10 14:06:47.563 EXECUTE_STATEMENT_RESTART
2025-06-10 14:06:47.576 Restarted 2 time(s)
2025-06-10 14:06:47.589
2025-06-10 14:06:47.600 EXECUTE_STATEMENT_RESTART
2025-06-10 14:06:47.613 Restarted 3 time(s)
2025-06-10 14:06:47.625
2025-06-10 14:06:47.635 EXECUTE_STATEMENT_RESTART
2025-06-10 14:06:47.643 Restarted 4 time(s)
2025-06-10 14:06:47.651 """
2025-06-10 14:06:47.657
2025-06-10 14:06:47.664 act.expected_stdout = expected_stdout_trace
2025-06-10 14:06:47.670 act.stdout = capsys.readouterr().out
2025-06-10 14:06:47.676 >           assert act.clean_stdout == act.clean_expected_stdout
2025-06-10 14:06:47.686 E           assert
2025-06-10 14:06:47.699 E               EXECUTE_STATEMENT_RESTART
2025-06-10 14:06:47.710 E               Restarted 1 time(s)
2025-06-10 14:06:47.718 E               EXECUTE_STATEMENT_RESTART
2025-06-10 14:06:47.730 E               Restarted 2 time(s)
2025-06-10 14:06:47.741 E               EXECUTE_STATEMENT_RESTART
2025-06-10 14:06:47.750 E               Restarted 3 time(s)
2025-06-10 14:06:47.764 E               EXECUTE_STATEMENT_RESTART
2025-06-10 14:06:47.775 E               Restarted 4 time(s)
2025-06-10 14:06:47.784 E             + EXECUTE_STATEMENT_RESTART
2025-06-10 14:06:47.790 E             + Restarted 5 time(s)
2025-06-10 14:06:47.795
2025-06-10 14:06:47.800 tests/functional/transactions/test_read_consist_sttm_merge_deny_multiple_matches.py:455: AssertionError
2025-06-10 14:06:47.805 ---------------------------- Captured stdout setup -----------------------------
2025-06-10 14:06:47.810 Creating db: localhost:/var/tmp/qa_2024/test_12376/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_12376/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12376/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12376/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
                act.reset()
    
            # < with act.trace
    
            allowed_patterns = \
            [
                 '\\)\\s+EXECUTE_STATEMENT_RESTART$'
                #,re.escape(SQL_TO_BE_RESTARTED)
                ,'^Restarted \\d+ time\\(s\\)'
            ]
            allowed_patterns = [re.compile(x) for x in allowed_patterns]
    
            for line in act.trace_log:
                if line.strip():
                    if act.match_any(line.strip(), allowed_patterns):
                        print(line.strip())
    
            expected_stdout_trace = f"""
                EXECUTE_STATEMENT_RESTART
                Restarted 1 time(s)
    
                EXECUTE_STATEMENT_RESTART
                Restarted 2 time(s)
    
                EXECUTE_STATEMENT_RESTART
                Restarted 3 time(s)
    
                EXECUTE_STATEMENT_RESTART
                Restarted 4 time(s)
            """
    
            act.expected_stdout = expected_stdout_trace
            act.stdout = capsys.readouterr().out
>           assert act.clean_stdout == act.clean_expected_stdout
E           assert   
E               EXECUTE_STATEMENT_RESTART
E               Restarted 1 time(s)
E               EXECUTE_STATEMENT_RESTART
E               Restarted 2 time(s)
E               EXECUTE_STATEMENT_RESTART
E               Restarted 3 time(s)
E               EXECUTE_STATEMENT_RESTART
E               Restarted 4 time(s)
E             + EXECUTE_STATEMENT_RESTART
E             + Restarted 5 time(s)

tests/functional/transactions/test_read_consist_sttm_merge_deny_multiple_matches.py:455: AssertionError
Full history of outcomes and elapsed time, ms:
NN SNAP_INFO CS_outcome SS_outcome CS_run_time SS_run_time CS_run_beg CS_run_end SS_run_beg SS_run_end
1 5.0.3.1674 2025.06.27 3ee5c P P 7346 6143 2025.06.29 13:30:26.437 2025.06.29 13:30:33.783 2025.06.29 12:00:35.847 2025.06.29 12:00:41.990
2 5.0.3.1657 2025.06.19 4bd4c P P 7241 5813 2025.06.27 12:41:59.376 2025.06.27 12:42:06.617 2025.06.27 11:18:16.916 2025.06.27 11:18:22.729
3 5.0.3.1657 2025.06.11 dae6f P P 7509 6248 2025.06.17 07:47:02.242 2025.06.17 07:47:09.751 2025.06.17 06:22:11.042 2025.06.17 06:22:17.290
4 5.0.3.1657 2025.06.10 dbc92 P P 7338 6464 2025.06.11 12:38:51.342 2025.06.11 12:38:58.680 2025.06.11 11:07:29.351 2025.06.11 11:07:35.815
5 5.0.3.1656 2025.05.20 c4b11 P F 7345 3141 2025.06.10 12:32:39.502 2025.06.10 12:32:46.847 2025.06.10 11:03:35.996 2025.06.10 11:03:39.137
6 5.0.3.1652 2025.05.13 f51c6 P P 7714 6468 2025.05.20 05:39:16.655 2025.05.20 05:39:24.369 2025.05.20 03:57:44.465 2025.05.20 03:57:50.933
7 5.0.3.1651 2025.04.30 141ef P P 7720 6627 2025.05.13 12:37:57.779 2025.05.13 12:38:05.499 2025.05.13 10:55:35.995 2025.05.13 10:55:42.622
8 5.0.3.1650 2025.04.28 4cbff P P 7707 6113 2025.05.01 12:10:55.402 2025.05.01 12:11:03.109 2025.05.01 10:29:26.804 2025.05.01 10:29:32.917
9 5.0.3.1649 2025.04.21 5b2d0 P P 7764 6370 2025.04.28 06:08:36.892 2025.04.28 06:08:44.656 2025.04.28 04:29:20.929 2025.04.28 04:29:27.299
10 5.0.3.1648 2025.04.18 2f4c5 P P 7801 6386 2025.04.20 06:00:31.179 2025.04.20 06:00:38.980 2025.04.20 04:23:02.850 2025.04.20 04:23:09.236
11 5.0.3.1635 2025.03.31 22ec6 P P 7810 6455 2025.04.18 12:23:33.592 2025.04.18 12:23:41.402 2025.04.18 10:42:56.701 2025.04.18 10:43:03.156
12 5.0.3.1633 2025.03.28 3123a P P 7591 5986 2025.03.31 10:55:51.279 2025.03.31 10:55:58.870 2025.03.31 09:21:59.570 2025.03.31 09:22:05.556
13 5.0.3.1633 2025.03.27 e0fb8 P P 7411 6819 2025.03.28 11:30:28.065 2025.03.28 11:30:35.476 2025.03.28 09:52:49.375 2025.03.28 09:52:56.194
14 5.0.3.1631 2025.03.21 1925b P P 8148 6478 2025.03.27 11:18:03.136 2025.03.27 11:18:11.284 2025.03.27 09:41:51.082 2025.03.27 09:41:57.560
15 5.0.3.1628 2025.03.14 16d05 P P 57149 51618 2025.03.17 08:54:15.100 2025.03.17 08:55:12.249 2025.03.17 07:08:52.862 2025.03.17 07:09:44.480
16 5.0.3.1627 2025.02.26 4e218 P P 58056 48432 2025.03.14 12:08:56.573 2025.03.14 12:09:54.629 2025.03.14 10:18:25.594 2025.03.14 10:19:14.026
17 5.0.3.1624 2025.02.25 dc3b2 P P 56419 49722 2025.02.26 10:58:02.190 2025.02.26 10:58:58.609 2025.02.26 09:16:54.725 2025.02.26 09:17:44.447
18 5.0.2.1615 2025.02.20 4a726 P P 56365 50340 2025.02.25 11:24:23.125 2025.02.25 11:25:19.490 2025.02.25 09:42:07.121 2025.02.25 09:42:57.461
19 5.0.2.1615 2025.02.14 9cb76 P P 56583 50075 2025.02.20 08:13:25.665 2025.02.20 08:14:22.248 2025.02.20 06:35:00.991 2025.02.20 06:35:51.066
20 5.0.2.1577 2024.12.24 3c80e P P 57175 49532 2025.02.14 11:27:13.975 2025.02.14 11:28:11.150 2025.02.14 09:48:01.228 2025.02.14 09:48:50.760
21 5.0.2.1576 2024.12.17 646b0 P P 51391 44768 2024.12.24 20:43:45.704 2024.12.24 20:44:37.095 2024.12.24 17:28:26.520 2024.12.24 17:29:11.288
22 5.0.2.1575 2024.12.08 63d39 P P 50940 44467 2024.12.16 08:24:48.589 2024.12.16 08:25:39.529 2024.12.16 07:11:00.679 2024.12.16 07:11:45.146
23 5.0.2.1567 2024.11.26 56e63 P P 52176 45530 2024.12.04 08:05:22.863 2024.12.04 08:06:15.039 2024.12.04 06:49:48.110 2024.12.04 06:50:33.640
24 5.0.2.1567 2024.11.21 96f61 P P 51315 44204 2024.11.26 05:46:37.397 2024.11.26 05:47:28.712 2024.11.26 04:34:37.981 2024.11.26 04:35:22.185
25 5.0.2.1567 2024.11.18 e1289 P P 51377 45165 2024.11.21 07:51:10.088 2024.11.21 07:52:01.465 2024.11.21 06:39:53.774 2024.11.21 06:40:38.939
26 5.0.2.1533 2024.10.23 0ec43 P P 52204 45012 2024.11.18 08:07:53.062 2024.11.18 08:08:45.266 2024.11.18 06:54:24.557 2024.11.18 06:55:09.569
27 5.0.2.1533 2024.10.22 8af7a P P 52035 45376 2024.10.23 10:05:04.641 2024.10.23 10:05:56.676 2024.10.23 08:50:20.282 2024.10.23 08:51:05.658
28 5.0.2.1532 2024.10.15 36dc0 P P 52089 45228 2024.10.22 20:16:54.205 2024.10.22 20:17:46.294 2024.10.22 19:02:43.304 2024.10.22 19:03:28.532
29 5.0.2.1518 2024.10.04 259ba P P 52308 45216 2024.10.15 09:50:42.003 2024.10.15 09:51:34.311 2024.10.15 08:36:10.588 2024.10.15 08:36:55.804
30 5.0.2.1518 2024.09.26 703cd P P 52579 45509 2024.10.03 08:18:13.033 2024.10.03 08:19:05.612 2024.10.03 07:01:31.264 2024.10.03 07:02:16.773
31 5.0.2.1489 2024.09.05 40838 P P 52753 45588 2024.09.25 08:19:09.856 2024.09.25 08:20:02.609 2024.09.25 07:01:33.417 2024.09.25 07:02:19.005
32 5.0.2.1489 2024.08.31 994a6 P P 66864 49870 2024.09.05 12:38:37.644 2024.09.05 12:39:44.508 2024.09.05 10:47:32.071 2024.09.05 10:48:21.941
33 5.0.2.1476 2024.08.09 843ea P P 66297 56538 2024.08.31 15:11:22.176 2024.08.31 15:12:28.473 2024.08.31 12:53:20.983 2024.08.31 12:54:17.521
34 5.0.1.1454 2024.08.08 30f9f P P 53993 47473 2024.08.09 08:55:20.240 2024.08.09 08:56:14.233 2024.08.09 07:36:59.792 2024.08.09 07:37:47.265
35 5.0.1.1453 2024.08.06 1b9d0 P P 54439 47665 2024.08.08 21:33:43.856 2024.08.08 21:34:38.295 2024.08.08 20:15:24.070 2024.08.08 20:16:11.735
36 5.0.1.1453 2024.07.30 48044 P P 54099 44591 2024.08.06 07:33:49.604 2024.08.06 07:34:43.703 2024.08.06 06:25:44.413 2024.08.06 06:26:29.004
37 5.0.1.1453 2024.07.28 8d956 P P 54014 44618 2024.07.30 07:27:48.777 2024.07.30 07:28:42.791 2024.07.30 06:20:42.973 2024.07.30 06:21:27.591
38 5.0.1.1429 2024.07.19 8ee90 P P 53308 45052 2024.07.27 07:27:52.628 2024.07.27 07:28:45.936 2024.07.27 06:19:58.844 2024.07.27 06:20:43.896
39 5.0.1.1428 2024.07.15 00392 P P 54009 45742 2024.07.19 07:20:45.774 2024.07.19 07:21:39.783 2024.07.19 06:14:09.974 2024.07.19 06:14:55.716
40 5.0.1.1428 2024.06.30 67a31 P P 53736 45770 2024.07.15 07:22:18.620 2024.07.15 07:23:12.356 2024.07.15 06:15:15.912 2024.07.15 06:16:01.682
41 5.0.1.1415 2024.06.11 31d74 P P 53348 45490 2024.06.22 07:09:14.216 2024.06.22 07:10:07.564 2024.06.22 06:05:05.529 2024.06.22 06:05:51.019

Elapsed time, ms. Chart for last 41 runs:

Last commits information (all timestamps in UTC):