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-01 17:49:16.075
2025-07-01 17:49:16.075 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-01 17:49:16.075 fn_worker_sql = WindowsPath('H:/QA/temp/qa2024.tmp/fbqa/test_12497/tmp_worker.sql')
2025-07-01 17:49:16.075 fn_worker_log = WindowsPath('H:/QA/temp/qa2024.tmp/fbqa/test_12497/tmp_worker.log')
2025-07-01 17:49:16.075 fn_worker_err = WindowsPath('H:/QA/temp/qa2024.tmp/fbqa/test_12497/tmp_worker.err')
2025-07-01 17:49:16.076 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-01 17:49:16.076
2025-07-01 17:49:16.076 @pytest.mark.trace
2025-07-01 17:49:16.076 @pytest.mark.version('>=4.0.2')
2025-07-01 17:49:16.076 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-01 17:49:16.076
2025-07-01 17:49:16.076 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-01 17:49:16.076
2025-07-01 17:49:16.076 for checked_mode in('table', 'view'):
2025-07-01 17:49:16.076 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-01 17:49:16.076
2025-07-01 17:49:16.076 # 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-01 17:49:16.076 for checked_DML in ('upd', 'mer', 'del', 'lok') if checked_mode == 'table' else ('upd', 'mer', 'del'):
2025-07-01 17:49:16.076
2025-07-01 17:49:16.076 ###################################################################################################################
2025-07-01 17:49:16.076 ### !!! NB !!! DO NOT SPLIT QUERIES ONTO MULTIPLE LINES OTHERWISE CHECK OF TRACE CONTENT WILL FAIL (SEE BELOW) ###
2025-07-01 17:49:16.076 ###################################################################################################################
2025-07-01 17:49:16.076 if checked_DML == 'upd':
2025-07-01 17:49:16.077 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-01 17:49:16.077 elif checked_DML == 'mer':
2025-07-01 17:49:16.077 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-01 17:49:16.077 elif checked_DML == 'del':
2025-07-01 17:49:16.077 SQL_TO_BE_RESTARTED = f'delete /* {SQL_TAG_THAT_WE_WAITING_FOR} */ from {target_obj} where id <= 2 order by id DESC'
2025-07-01 17:49:16.077 elif checked_DML == 'lok':
2025-07-01 17:49:16.077 # ::: NB :::
2025-07-01 17:49:16.077 # We must SUPRESS sending record to client for SELECT WITH LOCK, otherwise error
2025-07-01 17:49:16.077 # deadlock/update conflist will raise immediately! Because of this, we enclose
2025-07-01 17:49:16.077 # such select into execute block which returns nothing:
2025-07-01 17:49:16.077 #
2025-07-01 17:49:16.077 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-01 17:49:16.077
2025-07-01 17:49:16.077 for main_iter in (0,1):
2025-07-01 17:49:16.077
2025-07-01 17:49:16.077 ###################################################################################
2025-07-01 17:49:16.077 ### 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-01 17:49:16.077 ###################################################################################
2025-07-01 17:49:16.077 ROWS_TO_ADD = 10 + 1 * main_iter
2025-07-01 17:49:16.077
2025-07-01 17:49:16.078 # Add either 12 or 14 rows, ID = 1,2, ..., 2+ROWS_TO_ADD:
2025-07-01 17:49:16.078 sql_addi = f'''
2025-07-01 17:49:16.078 set term ^;
2025-07-01 17:49:16.078 execute block as
2025-07-01 17:49:16.078 begin
2025-07-01 17:49:16.078 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-01 17:49:16.078 end
2025-07-01 17:49:16.078 ^
2025-07-01 17:49:16.078 set term ;^
2025-07-01 17:49:16.078 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-01 17:49:16.078 commit;
2025-07-01 17:49:16.078 '''
2025-07-01 17:49:16.078
2025-07-01 17:49:16.078 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-07-01 17:49:16.078 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-01 17:49:16.078 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-01 17:49:16.078 assert act.stderr == ''
2025-07-01 17:49:16.078 act.reset()
2025-07-01 17:49:16.078
2025-07-01 17:49:16.078 # Get Firebird log before test
2025-07-01 17:49:16.079 fb_log_init = act.get_firebird_log()
2025-07-01 17:49:16.079
2025-07-01 17:49:16.079 trace_cfg_items = [
2025-07-01 17:49:16.079 'time_threshold = 0',
2025-07-01 17:49:16.079 'log_errors = true',
2025-07-01 17:49:16.079 'log_statement_start = true',
2025-07-01 17:49:16.079 'log_statement_finish = true',
2025-07-01 17:49:16.079 ]
2025-07-01 17:49:16.079
2025-07-01 17:49:16.079 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-01 17:49:16.079
2025-07-01 17:49:16.079 with act.db.connect() as con_lock_1, act.db.connect() as con_lock_2, act.db.connect() as con_monitoring:
2025-07-01 17:49:16.079
2025-07-01 17:49:16.079 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-01 17:49:16.079 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-01 17:49:16.079 cur_monitoring = tx_monitoring.cursor()
2025-07-01 17:49:16.079
2025-07-01 17:49:16.079 locked_rows_map ={} # K = 0 or 1 (locker_1 and locker_2 respectively); V = ID of locked row
2025-07-01 17:49:16.079
2025-07-01 17:49:16.079 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-01 17:49:16.080 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-01 17:49:16.080 c.execute_immediate(sttm)
2025-07-01 17:49:16.080
2025-07-01 17:49:16.080 con_monitoring.execute_immediate("execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'MONITOR'); end")
2025-07-01 17:49:16.080
2025-07-01 17:49:16.080 #########################
2025-07-01 17:49:16.080 ### L O C K E R - 1 ###
2025-07-01 17:49:16.080 #########################
2025-07-01 17:49:16.080 locked_rows_map[ 1 ] = 1
2025-07-01 17:49:16.080 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = {locked_rows_map[1]} /* locker-1 */' )
2025-07-01 17:49:16.080
2025-07-01 17:49:16.080 # Run UPDATE | DELETE | MERGE | SELECT WITH LOCK -- see {SQL_TO_BE_RESTARTED}
2025-07-01 17:49:16.080 # Every statement ends with 'ORDER BY ID DESC' and must hang because of lockes:
2025-07-01 17:49:16.080
2025-07-01 17:49:16.080 worker_sql = f'''
2025-07-01 17:49:16.080 set list on;
2025-07-01 17:49:16.080 set autoddl off;
2025-07-01 17:49:16.080 set term ^;
2025-07-01 17:49:16.080 execute block as
2025-07-01 17:49:16.080 begin
2025-07-01 17:49:16.080 rdb$set_context('USER_SESSION','WHO', 'WORKER');
2025-07-01 17:49:16.081 end
2025-07-01 17:49:16.081 ^
2025-07-01 17:49:16.081 set term ;^
2025-07-01 17:49:16.081 commit;
2025-07-01 17:49:16.081 SET KEEP_TRAN_PARAMS ON;
2025-07-01 17:49:16.081 set transaction read committed read consistency;
2025-07-01 17:49:16.081 set list off;
2025-07-01 17:49:16.081 set wng off;
2025-07-01 17:49:16.081
2025-07-01 17:49:16.081 set count on;
2025-07-01 17:49:16.081 set term ^;
2025-07-01 17:49:16.081 {SQL_TO_BE_RESTARTED}
2025-07-01 17:49:16.081 ^
2025-07-01 17:49:16.081 set term ;^
2025-07-01 17:49:16.081
2025-07-01 17:49:16.081 -- check results:
2025-07-01 17:49:16.081 -- ###############
2025-07-01 17:49:16.081 --set echo on;
2025-07-01 17:49:16.081 select id from {target_obj} order by id;
2025-07-01 17:49:16.082
2025-07-01 17:49:16.082 select v.old_id, v.op, v.snap_no_rank
2025-07-01 17:49:16.082 from v_worker_log v
2025-07-01 17:49:16.082 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-01 17:49:16.082 --set echo off;
2025-07-01 17:49:16.082
2025-07-01 17:49:16.082 --set width who 10;
2025-07-01 17:49:16.082 -- DO NOT check this! Values can differ here from one run to another!
2025-07-01 17:49:16.082 -- select id, trn, who, old_id, new_id, op, rec_vers, global_cn, snap_no from tlog_done order by id;
2025-07-01 17:49:16.082 rollback;
2025-07-01 17:49:16.082
2025-07-01 17:49:16.082 '''
2025-07-01 17:49:16.082
2025-07-01 17:49:16.082 fn_worker_sql.write_text(worker_sql)
2025-07-01 17:49:16.082
2025-07-01 17:49:16.082 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-01 17:49:16.082
2025-07-01 17:49:16.082 ############################################################################
2025-07-01 17:49:16.082 ### L A U N C H W O R K E R U S I N G I S Q L, A S Y N C. ###
2025-07-01 17:49:16.082 ############################################################################
2025-07-01 17:49:16.083 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-01 17:49:16.083 '-user', act.db.user,
2025-07-01 17:49:16.083 '-password', act.db.password,
2025-07-01 17:49:16.083 '-pag', '999999',
2025-07-01 17:49:16.083 act.db.dsn
2025-07-01 17:49:16.083 ],
2025-07-01 17:49:16.083 stdout = hang_out,
2025-07-01 17:49:16.083 stderr = hang_err
2025-07-01 17:49:16.083 )
2025-07-01 17:49:16.083
2025-07-01 17:49:16.083 # update ... set id = id * 100 where id <= 2 order by id DESC
2025-07-01 17:49:16.083
2025-07-01 17:49:16.083 # NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- see above SQL_TO_BE_RESTARTED
2025-07-01 17:49:16.083 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 17:49:16.083 #
2025-07-01 17:49:16.083 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-01 17:49:16.083
2025-07-01 17:49:16.083 cur_lock_1 = con_lock_1.cursor()
2025-07-01 17:49:16.083 cur_lock_2 = con_lock_2.cursor()
2025-07-01 17:49:16.083 sttm = f'update {target_obj} set id = ? where abs( id ) = ?'
2025-07-01 17:49:16.084
2025-07-01 17:49:16.084 for i in range(0,ROWS_TO_ADD):
2025-07-01 17:49:16.084 v_id = 2 + ROWS_TO_ADD-i
2025-07-01 17:49:16.084 if i % 2 == 0:
2025-07-01 17:49:16.084 # 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-01 17:49:16.084 # 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-01 17:49:16.084 locked_rows_map[ i % 2 ] = -abs( v_id )
2025-07-01 17:49:16.084 cur_lock_2.execute( sttm + f"/* locker-2 lup, ini-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-01 17:49:16.084 con_lock_2.commit()
2025-07-01 17:49:16.084 cur_lock_2.execute( sttm + f"/* locker-2 lup, re-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-01 17:49:16.084 con_lock_1.commit() # releases ID = locked_rows_map[ 0 ]
2025-07-01 17:49:16.084 else:
2025-07-01 17:49:16.084 # 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-01 17:49:16.084 # 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-01 17:49:16.084 locked_rows_map[ i % 2 ] = -abs( v_id )
2025-07-01 17:49:16.084 cur_lock_1.execute( sttm + f"/* locker-1 lup, ini-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-01 17:49:16.084 con_lock_1.commit()
2025-07-01 17:49:16.084 cur_lock_1.execute( sttm + f"/* locker-1 lup, re-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-01 17:49:16.084 con_lock_2.commit() # releases ID = locked_rows_map[ 1 ]
2025-07-01 17:49:16.084
2025-07-01 17:49:16.087 # NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- see above SQL_TO_BE_RESTARTED
2025-07-01 17:49:16.087 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 17:49:16.088 #
2025-07-01 17:49:16.088 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-01 17:49:16.088
2025-07-01 17:49:16.088 cur_monitoring.execute(f'select count(*) from {target_obj}')
2025-07-01 17:49:16.088 for r in cur_monitoring:
2025-07-01 17:49:16.088 target_obj_cnt = r[0]
2025-07-01 17:49:16.088 #target_obj_cnt = cur_monitoring.fetchall()[0]
2025-07-01 17:49:16.088
2025-07-01 17:49:16.088 if ROWS_TO_ADD % 2 == 0:
2025-07-01 17:49:16.088 if con_lock_2.is_active():
2025-07-01 17:49:16.088 con_lock_2.commit()
2025-07-01 17:49:16.088 con_lock_1.commit()
2025-07-01 17:49:16.088 else:
2025-07-01 17:49:16.088 if con_lock_1.is_active():
2025-07-01 17:49:16.088 con_lock_1.commit()
2025-07-01 17:49:16.088 con_lock_2.commit()
2025-07-01 17:49:16.088
2025-07-01 17:49:16.088 # Here we wait for ISQL complete its mission:
2025-07-01 17:49:16.088 p_worker.wait()
2025-07-01 17:49:16.088
2025-07-01 17:49:16.089 #< with ... con_lock_1, ... con_lock_2
2025-07-01 17:49:16.089
2025-07-01 17:49:16.089
2025-07-01 17:49:16.089
2025-07-01 17:49:16.089 #####################################################
2025-07-01 17:49:16.089 ### check content of 'TEST' and 'TLOG*' tables ###
2025-07-01 17:49:16.089 #####################################################
2025-07-01 17:49:16.089
2025-07-01 17:49:16.089 print( f'checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = {main_iter}, number of added rows: {ROWS_TO_ADD}' )
2025-07-01 17:49:16.089
2025-07-01 17:49:16.089 for g in (fn_worker_log, fn_worker_err):
2025-07-01 17:49:16.089 logname = 'STDLOG' if g == fn_worker_log else 'STDERR'
2025-07-01 17:49:16.089 with g.open() as f:
2025-07-01 17:49:16.089 for line in f:
2025-07-01 17:49:16.089 if line.strip():
2025-07-01 17:49:16.089 print( f'checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = {main_iter}, worker {logname}: {line}' )
2025-07-01 17:49:16.089
2025-07-01 17:49:16.089 expected_stdout_worker = f"""
2025-07-01 17:49:16.089 """
2025-07-01 17:49:16.089 if main_iter == 0:
2025-07-01 17:49:16.089 if checked_DML in ('upd', 'mer'):
2025-07-01 17:49:16.090 expected_stdout_worker = f"""
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, number of added rows: 10
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ID
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: =======
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1200
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1100
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1000
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -900
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -800
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -700
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -600
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -500
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -400
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -300
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 100
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 200
2025-07-01 17:49:16.090 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ======= ====== =====================
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 1
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 2
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 2
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 3
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 3
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 4
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 4
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 5
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 5
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 6
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 6
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 7
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 7
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 8
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 8
2025-07-01 17:49:16.091 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 9
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 9
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 10
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 10
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -3 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -4 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -5 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -6 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -7 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -8 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -9 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -10 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -11 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -12 UPD 11
2025-07-01 17:49:16.092 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 31
2025-07-01 17:49:16.092 """
2025-07-01 17:49:16.092 elif checked_DML == 'lok':
2025-07-01 17:49:16.093 expected_stdout_worker = f"""
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, number of added rows: 10
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ID
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: =======
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -12
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -11
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -10
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -9
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -8
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -7
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -6
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -5
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -4
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -3
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
2025-07-01 17:49:16.093 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 0
2025-07-01 17:49:16.094 """
2025-07-01 17:49:16.094 elif checked_DML == 'del':
2025-07-01 17:49:16.094 expected_stdout_worker = f"""
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, number of added rows: 10
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 12
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 0
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: ======= ====== =====================
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 1
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 2
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 2
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 3
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 3
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 4
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 4
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 5
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 5
2025-07-01 17:49:16.094 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 6
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 6
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 7
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 7
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 8
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 8
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 9
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 9
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 10
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 10
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 11
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 11
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -3 DEL 11
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -4 DEL 11
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -5 DEL 11
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -6 DEL 11
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -7 DEL 11
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -8 DEL 11
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -9 DEL 11
2025-07-01 17:49:16.095 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -10 DEL 11
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -11 DEL 11
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -12 DEL 11
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 31
2025-07-01 17:49:16.096 """
2025-07-01 17:49:16.096 else:
2025-07-01 17:49:16.096 if checked_DML in ('upd', 'mer'):
2025-07-01 17:49:16.096 expected_stdout_worker = f"""
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, number of added rows: 11
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 2
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ID
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: =======
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -13
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -12
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -11
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -10
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -9
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -8
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -7
2025-07-01 17:49:16.096 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -6
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -5
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -4
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -3
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 13
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ======= ====== =====================
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 1
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 2
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 2
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 3
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 3
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 4
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 4
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 5
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 5
2025-07-01 17:49:16.097 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 6
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 6
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 7
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 7
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 8
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 8
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 9
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 9
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 10
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 10
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 11
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 11
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 21
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: deadlock
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: -update conflicts with concurrent update
2025-07-01 17:49:16.098 concurrent transaction number is
2025-07-01 17:49:16.098 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR:
2025-07-01 17:49:16.098 """
2025-07-01 17:49:16.098 elif checked_DML == 'lok':
2025-07-01 17:49:16.099 expected_stdout_worker = f"""
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, number of added rows: 11
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ID
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: =======
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -13
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -12
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -11
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -10
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -9
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -8
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -7
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -6
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -5
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -4
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -3
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 13
2025-07-01 17:49:16.099 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 0
2025-07-01 17:49:16.100 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
2025-07-01 17:49:16.102 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: deadlock
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: -update conflicts with concurrent update
2025-07-01 17:49:16.103 concurrent transaction number is
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR:
2025-07-01 17:49:16.103 """
2025-07-01 17:49:16.103 elif checked_DML == 'del':
2025-07-01 17:49:16.103 expected_stdout_worker = f"""
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = del, iter = 1, number of added rows: 11
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 2
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: ID
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: =======
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -13
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -12
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -11
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -10
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -9
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -8
2025-07-01 17:49:16.103 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -7
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -6
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -5
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -4
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -3
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 13
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: ======= ====== =====================
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 1
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 2
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 2
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 3
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 3
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 4
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 4
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 5
2025-07-01 17:49:16.104 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 5
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 6
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 6
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 7
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 7
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 8
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 8
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 9
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 9
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 10
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 10
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 11
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 11
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 21
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: deadlock
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: -update conflicts with concurrent update
2025-07-01 17:49:16.105 concurrent transaction number is
2025-07-01 17:49:16.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR:
2025-07-01 17:49:16.105 """
2025-07-01 17:49:16.106
2025-07-01 17:49:16.106 act.expected_stdout = expected_stdout_worker
2025-07-01 17:49:16.106 act.stdout = capsys.readouterr().out
2025-07-01 17:49:16.106 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-01 17:49:16.106 E assert
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, number of added rows: 10
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: ID
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1200
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1100
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1000
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -900
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -800
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -700
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -600
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -500
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -400
2025-07-01 17:49:16.106 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -300
2025-07-01 17:49:16.107 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 100
2025-07-01 17:49:16.107 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 200
2025-07-01 17:49:16.107 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
2025-07-01 17:49:16.107 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 17:49:16.107 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
2025-07-01 17:49:16.107 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 1
2025-07-01 17:49:16.107 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 1
2025-07-01 17:49:16.108 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 2
2025-07-01 17:49:16.108 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 2
2025-07-01 17:49:16.108 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 2
2025-07-01 17:49:16.108 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 2
2025-07-01 17:49:16.108 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 3
2025-07-01 17:49:16.108 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 3
2025-07-01 17:49:16.108 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 3
2025-07-01 17:49:16.108 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 3
2025-07-01 17:49:16.108 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 4
2025-07-01 17:49:16.108 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 4
2025-07-01 17:49:16.108 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 4
2025-07-01 17:49:16.109 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 4
2025-07-01 17:49:16.109 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 5
2025-07-01 17:49:16.109 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 5
2025-07-01 17:49:16.109 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 5
2025-07-01 17:49:16.109 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 5
2025-07-01 17:49:16.109 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 6
2025-07-01 17:49:16.109 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 6
2025-07-01 17:49:16.109 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 6
2025-07-01 17:49:16.109 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 6
2025-07-01 17:49:16.109 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 7
2025-07-01 17:49:16.109 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 7
2025-07-01 17:49:16.109 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 7
2025-07-01 17:49:16.109 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 7
2025-07-01 17:49:16.110 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 8
2025-07-01 17:49:16.110 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 8
2025-07-01 17:49:16.110 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 8
2025-07-01 17:49:16.110 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 8
2025-07-01 17:49:16.110 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 9
2025-07-01 17:49:16.110 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 9
2025-07-01 17:49:16.110 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 9
2025-07-01 17:49:16.110 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 9
2025-07-01 17:49:16.110 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 10
2025-07-01 17:49:16.110 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 10
2025-07-01 17:49:16.110 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 10
2025-07-01 17:49:16.110 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 10
2025-07-01 17:49:16.110 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 11
2025-07-01 17:49:16.111 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 11
2025-07-01 17:49:16.111 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 11
2025-07-01 17:49:16.111 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 11
2025-07-01 17:49:16.111 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3 UPD 11
2025-07-01 17:49:16.111 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3UPD 11
2025-07-01 17:49:16.111 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4 UPD 11
2025-07-01 17:49:16.111 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4UPD 11
2025-07-01 17:49:16.111 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5 UPD 11
2025-07-01 17:49:16.111 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5UPD 11
2025-07-01 17:49:16.111 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6 UPD 11
2025-07-01 17:49:16.111 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6UPD 11
2025-07-01 17:49:16.111 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7 UPD 11
2025-07-01 17:49:16.112 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7UPD 11
2025-07-01 17:49:16.112 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8 UPD 11
2025-07-01 17:49:16.112 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8UPD 11
2025-07-01 17:49:16.112 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9 UPD 11
2025-07-01 17:49:16.112 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9UPD 11
2025-07-01 17:49:16.112 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10 UPD 11
2025-07-01 17:49:16.112 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10UPD 11
2025-07-01 17:49:16.112 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11 UPD 11
2025-07-01 17:49:16.112 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11UPD 11
2025-07-01 17:49:16.112 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12 UPD 11
2025-07-01 17:49:16.112 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12UPD 11
2025-07-01 17:49:16.112 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 31
2025-07-01 17:49:16.112
2025-07-01 17:49:16.113 tests\functional\transactions\test_read_consist_sttm_restart_max_limit.py:631: AssertionError
2025-07-01 17:49:16.113 ---------------------------- Captured stdout setup ----------------------------
2025-07-01 17:49:16.113 Creating db: localhost:H:\QA\temp\qa2024.tmp\fbqa\test_12497\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 = WindowsPath('H:/QA/temp/qa2024.tmp/fbqa/test_12497/tmp_worker.sql')
fn_worker_log = WindowsPath('H:/QA/temp/qa2024.tmp/fbqa/test_12497/tmp_worker.log')
fn_worker_err = WindowsPath('H:/QA/temp/qa2024.tmp/fbqa/test_12497/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
|