2 @message |
assert
checked_mode: table, checked_DML upd, iter 0, number of added rows: 10
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: ID
checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1200
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1100
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1000
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -900
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -800
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -700
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -600
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -500
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -400
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -300
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 100
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 200
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 1
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 1
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 2
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 2
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 2
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 2
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 3
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 3
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 3
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 3
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 4
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 4
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 4
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 4
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 5
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 5
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 5
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 5
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 6
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 6
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 6
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 6
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 7
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 7
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 7
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 7
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 8
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 8
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 8
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 8
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 9
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 9
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 9
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 9
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 10
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 10
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 10
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 10
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12UPD 11
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 31
LOG DETAILS:
2025-07-02 06:07:31.647
2025-07-02 06:07:31.655 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-02 06:07:31.662 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12476/tmp_worker.sql')
2025-07-02 06:07:31.671 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12476/tmp_worker.log')
2025-07-02 06:07:31.683 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12476/tmp_worker.err')
2025-07-02 06:07:31.693 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-02 06:07:31.700
2025-07-02 06:07:31.706 @pytest.mark.trace
2025-07-02 06:07:31.714 @pytest.mark.version('>=4.0.2')
2025-07-02 06:07:31.725 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-02 06:07:31.737
2025-07-02 06:07:31.744 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-02 06:07:31.751
2025-07-02 06:07:31.759 for checked_mode in('table', 'view'):
2025-07-02 06:07:31.765 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-02 06:07:31.771
2025-07-02 06:07:31.778 # NB: for 'lok' can not be used with a VIEW, error: "336397326 : WITH LOCK can be used only with a single physical table"
2025-07-02 06:07:31.786 for checked_DML in ('upd', 'mer', 'del', 'lok') if checked_mode == 'table' else ('upd', 'mer', 'del'):
2025-07-02 06:07:31.797
2025-07-02 06:07:31.807 ###################################################################################################################
2025-07-02 06:07:31.814 ### !!! NB !!! DO NOT SPLIT QUERIES ONTO MULTIPLE LINES OTHERWISE CHECK OF TRACE CONTENT WILL FAIL (SEE BELOW) ###
2025-07-02 06:07:31.820 ###################################################################################################################
2025-07-02 06:07:31.827 if checked_DML == 'upd':
2025-07-02 06:07:31.840 SQL_TO_BE_RESTARTED = f'update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = id * 100 where id <= 2 order by id DESC'
2025-07-02 06:07:31.853 elif checked_DML == 'mer':
2025-07-02 06:07:31.865 SQL_TO_BE_RESTARTED = f'merge /* {SQL_TAG_THAT_WE_WAITING_FOR} */ into {target_obj} t using (select x.id from {target_obj} x where x.id <= 2 order by id DESC) s on t.id = s.id when matched then update set t.id = s.id * 100'
2025-07-02 06:07:31.875 elif checked_DML == 'del':
2025-07-02 06:07:31.887 SQL_TO_BE_RESTARTED = f'delete /* {SQL_TAG_THAT_WE_WAITING_FOR} */ from {target_obj} where id <= 2 order by id DESC'
2025-07-02 06:07:31.897 elif checked_DML == 'lok':
2025-07-02 06:07:31.907 # ::: NB :::
2025-07-02 06:07:31.919 # We must SUPRESS sending record to client for SELECT WITH LOCK, otherwise error
2025-07-02 06:07:31.930 # deadlock/update conflist will raise immediately! Because of this, we enclose
2025-07-02 06:07:31.942 # such select into execute block which returns nothing:
2025-07-02 06:07:31.954 #
2025-07-02 06:07:31.967 SQL_TO_BE_RESTARTED = f'execute block /* {SQL_TAG_THAT_WE_WAITING_FOR} */ as declare c int; begin for select id from {target_obj} where id<=2 order by id DESC with lock into c do begin end end'
2025-07-02 06:07:31.976
2025-07-02 06:07:31.985 for main_iter in (0,1):
2025-07-02 06:07:31.992
2025-07-02 06:07:32.000 ###################################################################################
2025-07-02 06:07:32.007 ### H O W M A N Y R E S T A R T S W E W A N T T O C H E C K ###
2025-07-02 06:07:32.013 ###################################################################################
2025-07-02 06:07:32.018 ROWS_TO_ADD = 10 + 1 * main_iter
2025-07-02 06:07:32.025
2025-07-02 06:07:32.031 # Add either 12 or 14 rows, ID = 1,2, ..., 2+ROWS_TO_ADD:
2025-07-02 06:07:32.038 sql_addi = f'''
2025-07-02 06:07:32.045 set term ^;
2025-07-02 06:07:32.051 execute block as
2025-07-02 06:07:32.058 begin
2025-07-02 06:07:32.069 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-02 06:07:32.080 end
2025-07-02 06:07:32.088 ^
2025-07-02 06:07:32.097 set term ;^
2025-07-02 06:07:32.112 insert into {target_obj}(id, x) select row_number()over(),row_number()over() from rdb$types rows (2 + {ROWS_TO_ADD}); -- <<< INITIAL DATA
2025-07-02 06:07:32.122 commit;
2025-07-02 06:07:32.129 '''
2025-07-02 06:07:32.136
2025-07-02 06:07:32.143 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-07-02 06:07:32.148 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-02 06:07:32.152 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-02 06:07:32.158 assert act.stderr == ''
2025-07-02 06:07:32.164 act.reset()
2025-07-02 06:07:32.170
2025-07-02 06:07:32.178 # Get Firebird log before test
2025-07-02 06:07:32.190 fb_log_init = act.get_firebird_log()
2025-07-02 06:07:32.199
2025-07-02 06:07:32.208 trace_cfg_items = [
2025-07-02 06:07:32.215 'time_threshold = 0',
2025-07-02 06:07:32.222 'log_errors = true',
2025-07-02 06:07:32.229 'log_statement_start = true',
2025-07-02 06:07:32.237 'log_statement_finish = true',
2025-07-02 06:07:32.243 ]
2025-07-02 06:07:32.249
2025-07-02 06:07:32.257 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-02 06:07:32.262
2025-07-02 06:07:32.269 with act.db.connect() as con_lock_1, act.db.connect() as con_lock_2, act.db.connect() as con_monitoring:
2025-07-02 06:07:32.276
2025-07-02 06:07:32.283 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-02 06:07:32.290 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-02 06:07:32.296 cur_monitoring = tx_monitoring.cursor()
2025-07-02 06:07:32.304
2025-07-02 06:07:32.310 locked_rows_map ={} # K = 0 or 1 (locker_1 and locker_2 respectively); V = ID of locked row
2025-07-02 06:07:32.317
2025-07-02 06:07:32.324 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-02 06:07:32.331 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-02 06:07:32.344 c.execute_immediate(sttm)
2025-07-02 06:07:32.355
2025-07-02 06:07:32.366 con_monitoring.execute_immediate("execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'MONITOR'); end")
2025-07-02 06:07:32.374
2025-07-02 06:07:32.384 #########################
2025-07-02 06:07:32.398 ### L O C K E R - 1 ###
2025-07-02 06:07:32.407 #########################
2025-07-02 06:07:32.414 locked_rows_map[ 1 ] = 1
2025-07-02 06:07:32.423 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = {locked_rows_map[1]} /* locker-1 */' )
2025-07-02 06:07:32.429
2025-07-02 06:07:32.436 # Run UPDATE | DELETE | MERGE | SELECT WITH LOCK -- see {SQL_TO_BE_RESTARTED}
2025-07-02 06:07:32.442 # Every statement ends with 'ORDER BY ID DESC' and must hang because of lockes:
2025-07-02 06:07:32.450
2025-07-02 06:07:32.457 worker_sql = f'''
2025-07-02 06:07:32.464 set list on;
2025-07-02 06:07:32.470 set autoddl off;
2025-07-02 06:07:32.476 set term ^;
2025-07-02 06:07:32.483 execute block as
2025-07-02 06:07:32.491 begin
2025-07-02 06:07:32.504 rdb$set_context('USER_SESSION','WHO', 'WORKER');
2025-07-02 06:07:32.516 end
2025-07-02 06:07:32.525 ^
2025-07-02 06:07:32.532 set term ;^
2025-07-02 06:07:32.538 commit;
2025-07-02 06:07:32.543 SET KEEP_TRAN_PARAMS ON;
2025-07-02 06:07:32.550 set transaction read committed read consistency;
2025-07-02 06:07:32.556 set list off;
2025-07-02 06:07:32.563 set wng off;
2025-07-02 06:07:32.572
2025-07-02 06:07:32.581 set count on;
2025-07-02 06:07:32.588 set term ^;
2025-07-02 06:07:32.600 {SQL_TO_BE_RESTARTED}
2025-07-02 06:07:32.614 ^
2025-07-02 06:07:32.627 set term ;^
2025-07-02 06:07:32.641
2025-07-02 06:07:32.652 -- check results:
2025-07-02 06:07:32.660 -- ###############
2025-07-02 06:07:32.665 --set echo on;
2025-07-02 06:07:32.671 select id from {target_obj} order by id;
2025-07-02 06:07:32.675
2025-07-02 06:07:32.680 select v.old_id, v.op, v.snap_no_rank
2025-07-02 06:07:32.685 from v_worker_log v
2025-07-02 06:07:32.692 where v.op = iif( '{checked_DML}' = 'mer', 'upd', '{checked_DML}'); -- 'UPD' or 'DEL'; for 'SELECT WITH LOCK' no records will be in v_worker_log.
2025-07-02 06:07:32.698 --set echo off;
2025-07-02 06:07:32.704
2025-07-02 06:07:32.711 --set width who 10;
2025-07-02 06:07:32.721 -- DO NOT check this! Values can differ here from one run to another!
2025-07-02 06:07:32.730 -- select id, trn, who, old_id, new_id, op, rec_vers, global_cn, snap_no from tlog_done order by id;
2025-07-02 06:07:32.741 rollback;
2025-07-02 06:07:32.751
2025-07-02 06:07:32.760 '''
2025-07-02 06:07:32.768
2025-07-02 06:07:32.775 fn_worker_sql.write_text(worker_sql)
2025-07-02 06:07:32.781
2025-07-02 06:07:32.787 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-02 06:07:32.795
2025-07-02 06:07:32.805 ############################################################################
2025-07-02 06:07:32.814 ### L A U N C H W O R K E R U S I N G I S Q L, A S Y N C. ###
2025-07-02 06:07:32.822 ############################################################################
2025-07-02 06:07:32.833 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-02 06:07:32.843 '-user', act.db.user,
2025-07-02 06:07:32.851 '-password', act.db.password,
2025-07-02 06:07:32.860 '-pag', '999999',
2025-07-02 06:07:32.868 act.db.dsn
2025-07-02 06:07:32.875 ],
2025-07-02 06:07:32.881 stdout = hang_out,
2025-07-02 06:07:32.887 stderr = hang_err
2025-07-02 06:07:32.895 )
2025-07-02 06:07:32.903
2025-07-02 06:07:32.911 # update ... set id = id * 100 where id <= 2 order by id DESC
2025-07-02 06:07:32.920
2025-07-02 06:07:32.930 # NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- see above SQL_TO_BE_RESTARTED
2025-07-02 06:07:32.943 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-02 06:07:32.955 #
2025-07-02 06:07:32.966 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set /* monitor-ini */ id=id where id=2', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-02 06:07:32.975
2025-07-02 06:07:32.986 cur_lock_1 = con_lock_1.cursor()
2025-07-02 06:07:32.996 cur_lock_2 = con_lock_2.cursor()
2025-07-02 06:07:33.009 sttm = f'update {target_obj} set id = ? where abs( id ) = ?'
2025-07-02 06:07:33.018
2025-07-02 06:07:33.027 for i in range(0,ROWS_TO_ADD):
2025-07-02 06:07:33.034 v_id = 2 + ROWS_TO_ADD-i
2025-07-02 06:07:33.041 if i % 2 == 0:
2025-07-02 06:07:33.049 # main_iter = 0: ROWS_TO_ADD = 10 ==> v_id = 2+10-0 = 12, 2+10-2 = 10, 2+10-4 = 8, 6, 4, 2
2025-07-02 06:07:33.060 # main_iter = 1: ROWS_TO_ADD = 12 ==> v_id = 2+12-0 = 14, 2+10-2 = 12, 2+10-4 = 10, 8, 6, 4
2025-07-02 06:07:33.069 locked_rows_map[ i % 2 ] = -abs( v_id )
2025-07-02 06:07:33.076 cur_lock_2.execute( sttm + f"/* locker-2 lup, ini-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-02 06:07:33.083 con_lock_2.commit()
2025-07-02 06:07:33.090 cur_lock_2.execute( sttm + f"/* locker-2 lup, re-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-02 06:07:33.100 con_lock_1.commit() # releases ID = locked_rows_map[ 0 ]
2025-07-02 06:07:33.110 else:
2025-07-02 06:07:33.117 # main_iter = 0: ROWS_TO_ADD = 10 ==> v_id = 2+10-1 = 11, 2+10-3 = 9, 2+10-5 = 7, 5, 3, 1
2025-07-02 06:07:33.129 # main_iter = 1: ROWS_TO_ADD = 12 ==> v_id = 2+12-1 = 13, 2+10-3 = 11, 2+10-5 = 9, 7, 5, 3
2025-07-02 06:07:33.139 locked_rows_map[ i % 2 ] = -abs( v_id )
2025-07-02 06:07:33.147 cur_lock_1.execute( sttm + f"/* locker-1 lup, ini-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-02 06:07:33.155 con_lock_1.commit()
2025-07-02 06:07:33.162 cur_lock_1.execute( sttm + f"/* locker-1 lup, re-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-02 06:07:33.168 con_lock_2.commit() # releases ID = locked_rows_map[ 1 ]
2025-07-02 06:07:33.173
2025-07-02 06:07:33.181 # NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- see above SQL_TO_BE_RESTARTED
2025-07-02 06:07:33.187 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-02 06:07:33.192 #
2025-07-02 06:07:33.198 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} /* monitor lup, i={i} */ set id=id where id = {locked_rows_map[ 1 - (i % 2) ]}', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-02 06:07:33.203
2025-07-02 06:07:33.209 cur_monitoring.execute(f'select count(*) from {target_obj}')
2025-07-02 06:07:33.215 for r in cur_monitoring:
2025-07-02 06:07:33.228 target_obj_cnt = r[0]
2025-07-02 06:07:33.235 #target_obj_cnt = cur_monitoring.fetchall()[0]
2025-07-02 06:07:33.242
2025-07-02 06:07:33.253 if ROWS_TO_ADD % 2 == 0:
2025-07-02 06:07:33.266 if con_lock_2.is_active():
2025-07-02 06:07:33.274 con_lock_2.commit()
2025-07-02 06:07:33.284 con_lock_1.commit()
2025-07-02 06:07:33.295 else:
2025-07-02 06:07:33.307 if con_lock_1.is_active():
2025-07-02 06:07:33.314 con_lock_1.commit()
2025-07-02 06:07:33.321 con_lock_2.commit()
2025-07-02 06:07:33.328
2025-07-02 06:07:33.334 # Here we wait for ISQL complete its mission:
2025-07-02 06:07:33.341 p_worker.wait()
2025-07-02 06:07:33.346
2025-07-02 06:07:33.353 #< with ... con_lock_1, ... con_lock_2
2025-07-02 06:07:33.359
2025-07-02 06:07:33.373
2025-07-02 06:07:33.384
2025-07-02 06:07:33.392 #####################################################
2025-07-02 06:07:33.399 ### check content of 'TEST' and 'TLOG*' tables ###
2025-07-02 06:07:33.404 #####################################################
2025-07-02 06:07:33.410
2025-07-02 06:07:33.418 print( f'checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = {main_iter}, number of added rows: {ROWS_TO_ADD}' )
2025-07-02 06:07:33.424
2025-07-02 06:07:33.435 for g in (fn_worker_log, fn_worker_err):
2025-07-02 06:07:33.447 logname = 'STDLOG' if g == fn_worker_log else 'STDERR'
2025-07-02 06:07:33.456 with g.open() as f:
2025-07-02 06:07:33.471 for line in f:
2025-07-02 06:07:33.482 if line.strip():
2025-07-02 06:07:33.491 print( f'checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = {main_iter}, worker {logname}: {line}' )
2025-07-02 06:07:33.498
2025-07-02 06:07:33.506 expected_stdout_worker = f"""
2025-07-02 06:07:33.513 """
2025-07-02 06:07:33.520 if main_iter == 0:
2025-07-02 06:07:33.526 if checked_DML in ('upd', 'mer'):
2025-07-02 06:07:33.534 expected_stdout_worker = f"""
2025-07-02 06:07:33.542 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, number of added rows: 10
2025-07-02 06:07:33.550 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
2025-07-02 06:07:33.559 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ID
2025-07-02 06:07:33.567 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: =======
2025-07-02 06:07:33.574 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1200
2025-07-02 06:07:33.581 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1100
2025-07-02 06:07:33.590 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1000
2025-07-02 06:07:33.599 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -900
2025-07-02 06:07:33.612 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -800
2025-07-02 06:07:33.622 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -700
2025-07-02 06:07:33.629 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -600
2025-07-02 06:07:33.637 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -500
2025-07-02 06:07:33.644 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -400
2025-07-02 06:07:33.653 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -300
2025-07-02 06:07:33.665 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 100
2025-07-02 06:07:33.677 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 200
2025-07-02 06:07:33.688 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
2025-07-02 06:07:33.696 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-02 06:07:33.708 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ======= ====== =====================
2025-07-02 06:07:33.720 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 1
2025-07-02 06:07:33.734 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 2
2025-07-02 06:07:33.744 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 2
2025-07-02 06:07:33.758 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 3
2025-07-02 06:07:33.768 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 3
2025-07-02 06:07:33.774 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 4
2025-07-02 06:07:33.780 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 4
2025-07-02 06:07:33.786 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 5
2025-07-02 06:07:33.794 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 5
2025-07-02 06:07:33.804 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 6
2025-07-02 06:07:33.814 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 6
2025-07-02 06:07:33.823 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 7
2025-07-02 06:07:33.831 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 7
2025-07-02 06:07:33.841 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 8
2025-07-02 06:07:33.854 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 8
2025-07-02 06:07:33.866 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 9
2025-07-02 06:07:33.876 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 9
2025-07-02 06:07:33.884 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 10
2025-07-02 06:07:33.892 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 10
2025-07-02 06:07:33.906 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 11
2025-07-02 06:07:33.914 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 11
2025-07-02 06:07:33.921 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -3 UPD 11
2025-07-02 06:07:33.931 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -4 UPD 11
2025-07-02 06:07:33.939 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -5 UPD 11
2025-07-02 06:07:33.949 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -6 UPD 11
2025-07-02 06:07:33.961 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -7 UPD 11
2025-07-02 06:07:33.971 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -8 UPD 11
2025-07-02 06:07:33.980 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -9 UPD 11
2025-07-02 06:07:33.995 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -10 UPD 11
2025-07-02 06:07:34.004 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -11 UPD 11
2025-07-02 06:07:34.013 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -12 UPD 11
2025-07-02 06:07:34.019 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 31
2025-07-02 06:07:34.024 """
2025-07-02 06:07:34.031 elif checked_DML == 'lok':
2025-07-02 06:07:34.037 expected_stdout_worker = f"""
2025-07-02 06:07:34.044 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, number of added rows: 10
2025-07-02 06:07:34.052 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ID
2025-07-02 06:07:34.059 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: =======
2025-07-02 06:07:34.068 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -12
2025-07-02 06:07:34.078 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -11
2025-07-02 06:07:34.086 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -10
2025-07-02 06:07:34.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -9
2025-07-02 06:07:34.109 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -8
2025-07-02 06:07:34.120 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -7
2025-07-02 06:07:34.130 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -6
2025-07-02 06:07:34.138 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -5
2025-07-02 06:07:34.146 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -4
2025-07-02 06:07:34.153 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -3
2025-07-02 06:07:34.160 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1
2025-07-02 06:07:34.168 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2
2025-07-02 06:07:34.177 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
2025-07-02 06:07:34.185 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 0
2025-07-02 06:07:34.192 """
2025-07-02 06:07:34.200 elif checked_DML == 'del':
2025-07-02 06:07:34.207 expected_stdout_worker = f"""
2025-07-02 06:07:34.215 checked_mode: {checked_mode}, checked_DML = del, iter = 0, number of added rows: 10
2025-07-02 06:07:34.230 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 12
2025-07-02 06:07:34.241 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 0
2025-07-02 06:07:34.254 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-02 06:07:34.268 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: ======= ====== =====================
2025-07-02 06:07:34.279 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 1
2025-07-02 06:07:34.289 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 2
2025-07-02 06:07:34.300 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 2
2025-07-02 06:07:34.313 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 3
2025-07-02 06:07:34.327 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 3
2025-07-02 06:07:34.338 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 4
2025-07-02 06:07:34.347 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 4
2025-07-02 06:07:34.355 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 5
2025-07-02 06:07:34.367 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 5
2025-07-02 06:07:34.377 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 6
2025-07-02 06:07:34.391 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 6
2025-07-02 06:07:34.402 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 7
2025-07-02 06:07:34.414 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 7
2025-07-02 06:07:34.428 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 8
2025-07-02 06:07:34.444 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 8
2025-07-02 06:07:34.457 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 9
2025-07-02 06:07:34.466 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 9
2025-07-02 06:07:34.474 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 10
2025-07-02 06:07:34.482 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 10
2025-07-02 06:07:34.489 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 11
2025-07-02 06:07:34.502 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 11
2025-07-02 06:07:34.511 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -3 DEL 11
2025-07-02 06:07:34.517 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -4 DEL 11
2025-07-02 06:07:34.523 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -5 DEL 11
2025-07-02 06:07:34.529 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -6 DEL 11
2025-07-02 06:07:34.534 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -7 DEL 11
2025-07-02 06:07:34.540 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -8 DEL 11
2025-07-02 06:07:34.545 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -9 DEL 11
2025-07-02 06:07:34.552 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -10 DEL 11
2025-07-02 06:07:34.563 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -11 DEL 11
2025-07-02 06:07:34.572 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -12 DEL 11
2025-07-02 06:07:34.579 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 31
2025-07-02 06:07:34.586 """
2025-07-02 06:07:34.592 else:
2025-07-02 06:07:34.598 if checked_DML in ('upd', 'mer'):
2025-07-02 06:07:34.604 expected_stdout_worker = f"""
2025-07-02 06:07:34.611 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, number of added rows: 11
2025-07-02 06:07:34.617 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 2
2025-07-02 06:07:34.624 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ID
2025-07-02 06:07:34.637 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: =======
2025-07-02 06:07:34.648 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -13
2025-07-02 06:07:34.660 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -12
2025-07-02 06:07:34.672 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -11
2025-07-02 06:07:34.682 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -10
2025-07-02 06:07:34.696 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -9
2025-07-02 06:07:34.707 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -8
2025-07-02 06:07:34.718 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -7
2025-07-02 06:07:34.727 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -6
2025-07-02 06:07:34.739 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -5
2025-07-02 06:07:34.751 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -4
2025-07-02 06:07:34.760 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -3
2025-07-02 06:07:34.768 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1
2025-07-02 06:07:34.776 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2
2025-07-02 06:07:34.783 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 13
2025-07-02 06:07:34.799 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-02 06:07:34.812 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ======= ====== =====================
2025-07-02 06:07:34.822 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 1
2025-07-02 06:07:34.831 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 2
2025-07-02 06:07:34.844 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 2
2025-07-02 06:07:34.853 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 3
2025-07-02 06:07:34.864 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 3
2025-07-02 06:07:34.876 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 4
2025-07-02 06:07:34.885 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 4
2025-07-02 06:07:34.896 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 5
2025-07-02 06:07:34.903 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 5
2025-07-02 06:07:34.910 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 6
2025-07-02 06:07:34.917 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 6
2025-07-02 06:07:34.923 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 7
2025-07-02 06:07:34.930 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 7
2025-07-02 06:07:34.937 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 8
2025-07-02 06:07:34.944 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 8
2025-07-02 06:07:34.951 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 9
2025-07-02 06:07:34.957 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 9
2025-07-02 06:07:34.964 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 10
2025-07-02 06:07:34.975 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 10
2025-07-02 06:07:34.989 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 11
2025-07-02 06:07:35.011 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 11
2025-07-02 06:07:35.021 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 21
2025-07-02 06:07:35.030 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
2025-07-02 06:07:35.038 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: deadlock
2025-07-02 06:07:35.045 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: -update conflicts with concurrent update
2025-07-02 06:07:35.051 concurrent transaction number is
2025-07-02 06:07:35.060 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR:
2025-07-02 06:07:35.071 """
2025-07-02 06:07:35.085 elif checked_DML == 'lok':
2025-07-02 06:07:35.095 expected_stdout_worker = f"""
2025-07-02 06:07:35.104 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, number of added rows: 11
2025-07-02 06:07:35.114 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ID
2025-07-02 06:07:35.126 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: =======
2025-07-02 06:07:35.136 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -13
2025-07-02 06:07:35.147 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -12
2025-07-02 06:07:35.158 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -11
2025-07-02 06:07:35.167 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -10
2025-07-02 06:07:35.181 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -9
2025-07-02 06:07:35.194 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -8
2025-07-02 06:07:35.208 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -7
2025-07-02 06:07:35.219 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -6
2025-07-02 06:07:35.229 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -5
2025-07-02 06:07:35.247 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -4
2025-07-02 06:07:35.258 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -3
2025-07-02 06:07:35.267 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1
2025-07-02 06:07:35.275 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2
2025-07-02 06:07:35.284 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 13
2025-07-02 06:07:35.297 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 0
2025-07-02 06:07:35.308 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
2025-07-02 06:07:35.321 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: deadlock
2025-07-02 06:07:35.332 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: -update conflicts with concurrent update
2025-07-02 06:07:35.341 concurrent transaction number is
2025-07-02 06:07:35.349 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR:
2025-07-02 06:07:35.355 """
2025-07-02 06:07:35.364 elif checked_DML == 'del':
2025-07-02 06:07:35.376 expected_stdout_worker = f"""
2025-07-02 06:07:35.388 checked_mode: {checked_mode}, checked_DML = del, iter = 1, number of added rows: 11
2025-07-02 06:07:35.398 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 2
2025-07-02 06:07:35.408 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: ID
2025-07-02 06:07:35.417 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: =======
2025-07-02 06:07:35.431 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -13
2025-07-02 06:07:35.441 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -12
2025-07-02 06:07:35.453 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -11
2025-07-02 06:07:35.465 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -10
2025-07-02 06:07:35.474 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -9
2025-07-02 06:07:35.485 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -8
2025-07-02 06:07:35.496 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -7
2025-07-02 06:07:35.509 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -6
2025-07-02 06:07:35.519 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -5
2025-07-02 06:07:35.529 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -4
2025-07-02 06:07:35.536 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -3
2025-07-02 06:07:35.544 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1
2025-07-02 06:07:35.551 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2
2025-07-02 06:07:35.558 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 13
2025-07-02 06:07:35.566 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-02 06:07:35.573 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: ======= ====== =====================
2025-07-02 06:07:35.580 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 1
2025-07-02 06:07:35.587 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 2
2025-07-02 06:07:35.595 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 2
2025-07-02 06:07:35.607 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 3
2025-07-02 06:07:35.616 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 3
2025-07-02 06:07:35.624 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 4
2025-07-02 06:07:35.631 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 4
2025-07-02 06:07:35.638 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 5
2025-07-02 06:07:35.652 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 5
2025-07-02 06:07:35.663 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 6
2025-07-02 06:07:35.675 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 6
2025-07-02 06:07:35.690 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 7
2025-07-02 06:07:35.699 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 7
2025-07-02 06:07:35.713 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 8
2025-07-02 06:07:35.721 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 8
2025-07-02 06:07:35.728 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 9
2025-07-02 06:07:35.737 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 9
2025-07-02 06:07:35.746 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 10
2025-07-02 06:07:35.754 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 10
2025-07-02 06:07:35.763 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 11
2025-07-02 06:07:35.775 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 11
2025-07-02 06:07:35.785 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 21
2025-07-02 06:07:35.793 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
2025-07-02 06:07:35.800 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: deadlock
2025-07-02 06:07:35.807 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: -update conflicts with concurrent update
2025-07-02 06:07:35.815 concurrent transaction number is
2025-07-02 06:07:35.828 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR:
2025-07-02 06:07:35.837 """
2025-07-02 06:07:35.844
2025-07-02 06:07:35.851 act.expected_stdout = expected_stdout_worker
2025-07-02 06:07:35.857 act.stdout = capsys.readouterr().out
2025-07-02 06:07:35.863 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-02 06:07:35.870 E assert
2025-07-02 06:07:35.876 E checked_mode: table, checked_DML upd, iter 0, number of added rows: 10
2025-07-02 06:07:35.883 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
2025-07-02 06:07:35.891 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: ID
2025-07-02 06:07:35.904 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
2025-07-02 06:07:35.917 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1200
2025-07-02 06:07:35.929 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1100
2025-07-02 06:07:35.940 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1000
2025-07-02 06:07:35.953 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -900
2025-07-02 06:07:35.964 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -800
2025-07-02 06:07:35.973 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -700
2025-07-02 06:07:35.981 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -600
2025-07-02 06:07:35.988 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -500
2025-07-02 06:07:35.995 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -400
2025-07-02 06:07:36.002 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -300
2025-07-02 06:07:36.013 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 100
2025-07-02 06:07:36.020 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 200
2025-07-02 06:07:36.027 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
2025-07-02 06:07:36.034 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-02 06:07:36.043 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
2025-07-02 06:07:36.049 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 1
2025-07-02 06:07:36.069 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 1
2025-07-02 06:07:36.076 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 2
2025-07-02 06:07:36.090 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 2
2025-07-02 06:07:36.100 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 2
2025-07-02 06:07:36.119 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 2
2025-07-02 06:07:36.127 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 3
2025-07-02 06:07:36.147 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 3
2025-07-02 06:07:36.154 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 3
2025-07-02 06:07:36.176 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 3
2025-07-02 06:07:36.189 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 4
2025-07-02 06:07:36.208 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 4
2025-07-02 06:07:36.216 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 4
2025-07-02 06:07:36.231 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 4
2025-07-02 06:07:36.242 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 5
2025-07-02 06:07:36.265 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 5
2025-07-02 06:07:36.276 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 5
2025-07-02 06:07:36.290 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 5
2025-07-02 06:07:36.302 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 6
2025-07-02 06:07:36.327 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 6
2025-07-02 06:07:36.339 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 6
2025-07-02 06:07:36.361 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 6
2025-07-02 06:07:36.371 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 7
2025-07-02 06:07:36.386 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 7
2025-07-02 06:07:36.395 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 7
2025-07-02 06:07:36.417 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 7
2025-07-02 06:07:36.425 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 8
2025-07-02 06:07:36.440 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 8
2025-07-02 06:07:36.447 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 8
2025-07-02 06:07:36.468 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 8
2025-07-02 06:07:36.479 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 9
2025-07-02 06:07:36.504 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 9
2025-07-02 06:07:36.517 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 9
2025-07-02 06:07:36.544 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 9
2025-07-02 06:07:36.551 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 10
2025-07-02 06:07:36.571 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 10
2025-07-02 06:07:36.582 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 10
2025-07-02 06:07:36.597 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 10
2025-07-02 06:07:36.602 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 11
2025-07-02 06:07:36.619 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 11
2025-07-02 06:07:36.630 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 11
2025-07-02 06:07:36.650 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 11
2025-07-02 06:07:36.665 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3 UPD 11
2025-07-02 06:07:36.685 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3UPD 11
2025-07-02 06:07:36.694 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4 UPD 11
2025-07-02 06:07:36.710 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4UPD 11
2025-07-02 06:07:36.720 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5 UPD 11
2025-07-02 06:07:36.738 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5UPD 11
2025-07-02 06:07:36.743 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6 UPD 11
2025-07-02 06:07:36.754 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6UPD 11
2025-07-02 06:07:36.763 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7 UPD 11
2025-07-02 06:07:36.784 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7UPD 11
2025-07-02 06:07:36.792 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8 UPD 11
2025-07-02 06:07:36.803 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8UPD 11
2025-07-02 06:07:36.809 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9 UPD 11
2025-07-02 06:07:36.819 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9UPD 11
2025-07-02 06:07:36.824 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10 UPD 11
2025-07-02 06:07:36.834 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10UPD 11
2025-07-02 06:07:36.840 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11 UPD 11
2025-07-02 06:07:36.856 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11UPD 11
2025-07-02 06:07:36.867 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12 UPD 11
2025-07-02 06:07:36.890 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12UPD 11
2025-07-02 06:07:36.897 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 31
2025-07-02 06:07:36.908
2025-07-02 06:07:36.922 tests/functional/transactions/test_read_consist_sttm_restart_max_limit.py:631: AssertionError
2025-07-02 06:07:36.934 ---------------------------- Captured stdout setup -----------------------------
2025-07-02 06:07:36.944 Creating db: localhost:/var/tmp/qa_2024/test_12476/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_12476/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12476/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12476/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'
# NB: for 'lok' can not be used with a VIEW, error: "336397326 : WITH LOCK can be used only with a single physical table"
for checked_DML in ('upd', 'mer', 'del', 'lok') if checked_mode == 'table' else ('upd', 'mer', 'del'):
###################################################################################################################
### !!! NB !!! DO NOT SPLIT QUERIES ONTO MULTIPLE LINES OTHERWISE CHECK OF TRACE CONTENT WILL FAIL (SEE BELOW) ###
###################################################################################################################
if checked_DML == 'upd':
SQL_TO_BE_RESTARTED = f'update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = id * 100 where id <= 2 order by id DESC'
elif checked_DML == 'mer':
SQL_TO_BE_RESTARTED = f'merge /* {SQL_TAG_THAT_WE_WAITING_FOR} */ into {target_obj} t using (select x.id from {target_obj} x where x.id <= 2 order by id DESC) s on t.id = s.id when matched then update set t.id = s.id * 100'
elif checked_DML == 'del':
SQL_TO_BE_RESTARTED = f'delete /* {SQL_TAG_THAT_WE_WAITING_FOR} */ from {target_obj} where id <= 2 order by id DESC'
elif checked_DML == 'lok':
# ::: NB :::
# We must SUPRESS sending record to client for SELECT WITH LOCK, otherwise error
# deadlock/update conflist will raise immediately! Because of this, we enclose
# such select into execute block which returns nothing:
#
SQL_TO_BE_RESTARTED = f'execute block /* {SQL_TAG_THAT_WE_WAITING_FOR} */ as declare c int; begin for select id from {target_obj} where id<=2 order by id DESC with lock into c do begin end end'
for main_iter in (0,1):
###################################################################################
### H O W M A N Y R E S T A R T S W E W A N T T O C H E C K ###
###################################################################################
ROWS_TO_ADD = 10 + 1 * main_iter
# Add either 12 or 14 rows, ID = 1,2, ..., 2+ROWS_TO_ADD:
sql_addi = f'''
set term ^;
execute block as
begin
rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
end
^
set term ;^
insert into {target_obj}(id, x) select row_number()over(),row_number()over() from rdb$types rows (2 + {ROWS_TO_ADD}); -- <<< INITIAL DATA
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()
# Get Firebird log before test
fb_log_init = act.get_firebird_log()
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()
locked_rows_map ={} # K = 0 or 1 (locker_1 and locker_2 respectively); V = ID of locked row
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)
con_monitoring.execute_immediate("execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'MONITOR'); end")
#########################
### L O C K E R - 1 ###
#########################
locked_rows_map[ 1 ] = 1
con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = {locked_rows_map[1]} /* locker-1 */' )
# Run UPDATE | DELETE | MERGE | SELECT WITH LOCK -- see {SQL_TO_BE_RESTARTED}
# Every statement ends with 'ORDER BY ID DESC' and must hang because of lockes:
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;
set term ^;
{SQL_TO_BE_RESTARTED}
^
set term ;^
-- check results:
-- ###############
--set echo on;
select id from {target_obj} order by id;
select v.old_id, v.op, v.snap_no_rank
from v_worker_log v
where v.op = iif( '{checked_DML}' = 'mer', 'upd', '{checked_DML}'); -- 'UPD' or 'DEL'; for 'SELECT WITH LOCK' no records will be in v_worker_log.
--set echo off;
--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
)
# update ... set id = id * 100 where id <= 2 order by id DESC
# NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- 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 /* monitor-ini */ id=id where id=2', SQL_TAG_THAT_WE_WAITING_FOR)
cur_lock_1 = con_lock_1.cursor()
cur_lock_2 = con_lock_2.cursor()
sttm = f'update {target_obj} set id = ? where abs( id ) = ?'
for i in range(0,ROWS_TO_ADD):
v_id = 2 + ROWS_TO_ADD-i
if i % 2 == 0:
# main_iter = 0: ROWS_TO_ADD = 10 ==> v_id = 2+10-0 = 12, 2+10-2 = 10, 2+10-4 = 8, 6, 4, 2
# main_iter = 1: ROWS_TO_ADD = 12 ==> v_id = 2+12-0 = 14, 2+10-2 = 12, 2+10-4 = 10, 8, 6, 4
locked_rows_map[ i % 2 ] = -abs( v_id )
cur_lock_2.execute( sttm + f"/* locker-2 lup, ini-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
con_lock_2.commit()
cur_lock_2.execute( sttm + f"/* locker-2 lup, re-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
con_lock_1.commit() # releases ID = locked_rows_map[ 0 ]
else:
# main_iter = 0: ROWS_TO_ADD = 10 ==> v_id = 2+10-1 = 11, 2+10-3 = 9, 2+10-5 = 7, 5, 3, 1
# main_iter = 1: ROWS_TO_ADD = 12 ==> v_id = 2+12-1 = 13, 2+10-3 = 11, 2+10-5 = 9, 7, 5, 3
locked_rows_map[ i % 2 ] = -abs( v_id )
cur_lock_1.execute( sttm + f"/* locker-1 lup, ini-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
con_lock_1.commit()
cur_lock_1.execute( sttm + f"/* locker-1 lup, re-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
con_lock_2.commit() # releases ID = locked_rows_map[ 1 ]
# NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- 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} /* monitor lup, i={i} */ set id=id where id = {locked_rows_map[ 1 - (i % 2) ]}', SQL_TAG_THAT_WE_WAITING_FOR)
cur_monitoring.execute(f'select count(*) from {target_obj}')
for r in cur_monitoring:
target_obj_cnt = r[0]
#target_obj_cnt = cur_monitoring.fetchall()[0]
if ROWS_TO_ADD % 2 == 0:
if con_lock_2.is_active():
con_lock_2.commit()
con_lock_1.commit()
else:
if con_lock_1.is_active():
con_lock_1.commit()
con_lock_2.commit()
# Here we wait for ISQL complete its mission:
p_worker.wait()
#< with ... con_lock_1, ... con_lock_2
#####################################################
### check content of 'TEST' and 'TLOG*' tables ###
#####################################################
print( f'checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = {main_iter}, number of added rows: {ROWS_TO_ADD}' )
for g in (fn_worker_log, fn_worker_err):
logname = 'STDLOG' if g == fn_worker_log else 'STDERR'
with g.open() as f:
for line in f:
if line.strip():
print( f'checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = {main_iter}, worker {logname}: {line}' )
expected_stdout_worker = f"""
"""
if main_iter == 0:
if checked_DML in ('upd', 'mer'):
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, number of added rows: 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ID
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: =======
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1200
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1100
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1000
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -900
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -800
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -700
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -600
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -500
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -400
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -300
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 100
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 200
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 1
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -3 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -4 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -5 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -6 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -7 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -8 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -9 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -10 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -11 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -12 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 31
"""
elif checked_DML == 'lok':
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, number of added rows: 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ID
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: =======
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 0
"""
elif checked_DML == 'del':
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = del, iter = 0, number of added rows: 10
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 12
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 0
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 1
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 2
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 2
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 3
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 3
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 4
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 4
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 5
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 5
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 6
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 6
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 7
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 7
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 8
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 8
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 9
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 9
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 10
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 10
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -3 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -4 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -5 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -6 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -7 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -8 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -9 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -10 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -11 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -12 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 31
"""
else:
if checked_DML in ('upd', 'mer'):
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, number of added rows: 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ID
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: =======
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -13
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 13
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 1
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 21
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: deadlock
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: -update conflicts with concurrent update
concurrent transaction number is
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR:
"""
elif checked_DML == 'lok':
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, number of added rows: 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ID
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: =======
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -13
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 13
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 0
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: deadlock
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: -update conflicts with concurrent update
concurrent transaction number is
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR:
"""
elif checked_DML == 'del':
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = del, iter = 1, number of added rows: 11
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 2
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: ID
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: =======
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -13
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -12
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -11
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -10
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -9
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -8
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -7
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -6
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -5
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -4
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -3
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 13
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 1
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 2
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 2
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 3
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 3
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 4
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 4
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 5
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 5
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 6
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 6
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 7
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 7
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 8
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 8
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 9
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 9
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 10
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 10
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 21
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: deadlock
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: -update conflicts with concurrent update
concurrent transaction number is
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker 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, checked_DML upd, iter 0, number of added rows: 10
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: ID
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1200
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1100
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1000
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -900
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -800
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -700
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -600
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -500
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -400
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -300
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 100
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 200
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 1
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 1
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 2
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 2
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 2
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 2
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 3
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 3
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 3
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 3
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 4
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 4
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 4
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 4
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 5
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 5
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 5
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 5
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 6
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 6
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 6
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 6
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 7
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 7
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 7
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 7
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 8
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 8
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 8
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 8
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 9
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 9
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 9
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 9
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 10
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 10
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 10
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 10
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12UPD 11
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 31
tests/functional/transactions/test_read_consist_sttm_restart_max_limit.py:631: AssertionError
|